More detailed subscriber event logging
[lispflowmapping.git] / mappingservice / implementation / src / main / java / org / opendaylight / lispflowmapping / implementation / lisp / MapServer.java
index 59f868bfe0d908b85fc8a94061b6cdf3ed0dc966..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,
@@ -9,13 +9,14 @@
 package org.opendaylight.lispflowmapping.implementation.lisp;
 
 import com.google.common.base.Preconditions;
+import com.google.common.collect.Maps;
+import com.google.common.util.concurrent.ThreadFactoryBuilder;
 import java.net.InetAddress;
 import java.net.NetworkInterface;
 import java.net.SocketException;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Enumeration;
-import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Iterator;
 import java.util.List;
@@ -25,12 +26,15 @@ import java.util.Set;
 import java.util.concurrent.Executors;
 import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.ScheduledFuture;
+import java.util.concurrent.ThreadFactory;
 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;
@@ -38,10 +42,12 @@ import org.opendaylight.lispflowmapping.interfaces.lisp.SmrEvent;
 import org.opendaylight.lispflowmapping.interfaces.mappingservice.IMappingService;
 import org.opendaylight.lispflowmapping.lisp.authentication.LispAuthenticationUtil;
 import org.opendaylight.lispflowmapping.lisp.type.LispMessage;
+import org.opendaylight.lispflowmapping.lisp.type.MappingData;
 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;
@@ -54,13 +60,11 @@ import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.ei
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapnotifymessage.MapNotifyBuilder;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapping.authkey.container.MappingAuthkey;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapping.record.container.MappingRecord;
-import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapping.record.container.MappingRecordBuilder;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapping.record.list.MappingRecordItem;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.mapping.record.list.MappingRecordItemBuilder;
 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;
@@ -89,6 +93,7 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         if (notificationService != null) {
             notificationService.registerNotificationListener(this);
         }
+        scheduler = new SmrScheduler();
     }
 
     @Override
@@ -99,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) {
@@ -114,21 +120,38 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
 
         for (MappingRecordItem record : mapRegister.getMappingRecordItem()) {
             MappingRecord mapping = record.getMappingRecord();
-
-            oldMapping = (MappingRecord) mapService.getMapping(MappingOrigin.Southbound, mapping.getEid());
-            mapService.addMapping(MappingOrigin.Southbound, mapping.getEid(), getSiteId(mapRegister), mapping, merge);
+            Eid eid = mapping.getEid();
+            MappingData mappingData = new MappingData(mapping, System.currentTimeMillis());
+            mappingData.setMergeEnabled(merge);
+            mappingData.setXtrId(mapRegister.getXtrId());
+
+            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
-                        ? (MappingRecord) mapService.getMapping(MappingOrigin.Southbound, mapping.getEid()) : mapping;
+                        ? getMappingRecord(mapService.getMapping(MappingOrigin.Southbound, eid)) : mapping;
 
                 if (mappingChanged(oldMapping, newMapping)) {
                     if (LOG.isDebugEnabled()) {
                         LOG.debug("Mapping update occured for {} SMRs will be sent for its subscribers.",
                                 LispAddressStringifier.getString(mapping.getEid()));
                     }
-                    subscribers = getSubscribers(mapping.getEid());
-                    sendSmrs(mapping, subscribers);
+                    subscribers = getSubscribers(eid);
+                    if (oldMapping != null && !oldMapping.getEid().equals(eid)) {
+                        subscribers = addParentSubscribers(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;
                 }
             }
@@ -142,8 +165,8 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
                 List<MappingRecordItem> mergedMappings = new ArrayList<MappingRecordItem>();
                 for (MappingRecordItem record : mapRegister.getMappingRecordItem()) {
                     MappingRecord mapping = record.getMappingRecord();
-                    MappingRecord currentRecord = (MappingRecord) mapService.getMapping(MappingOrigin.Southbound,
-                            mapping.getEid());
+                    MappingRecord currentRecord = getMappingRecord(mapService.getMapping(MappingOrigin.Southbound,
+                            mapping.getEid()));
                     mergedMappings.add(new MappingRecordItemBuilder().setMappingRecord(currentRecord).build());
                     Set<IpAddressBinary> sourceRlocs = (Set<IpAddressBinary>) mapService.getData(
                             MappingOrigin.Southbound, mapping.getEid(), SubKeys.SRC_RLOCS);
@@ -183,25 +206,36 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         return rlocs;
     }
 
-    private SiteId getSiteId(MapRegister mapRegister) {
+    private static SiteId getSiteId(MapRegister mapRegister) {
         return (mapRegister.getSiteId() != null) ? new SiteId(mapRegister.getSiteId()) : null;
     }
 
+    private static MappingRecord getMappingRecord(MappingData mappingData) {
+        return (mappingData != null) ? mappingData.getRecord() : null;
+    }
+
     @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(notification.getMappingRecord(), getSubscribers(notification.getMappingRecord().getEid()));
-            }
-            if (notification.getChangeType().equals(MappingChange.Removed)) {
-                removeSubscribers(notification.getMappingRecord().getEid());
+                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);
+                }
             }
         }
     }
 
     private static boolean mappingChanged(MappingRecord oldMapping, MappingRecord newMapping) {
         // We only check for fields we care about
-        // XXX: This code needs to be checked and updated when the YANG model is modified
+        // XXX: This code needs to be checked and updated when the YANG model for MappingRecord is modified
         Preconditions.checkNotNull(newMapping, "The new mapping should never be null");
         if (oldMapping == null) {
             LOG.trace("mappingChanged(): old mapping is null");
@@ -225,41 +259,50 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         return false;
     }
 
-    private void sendSmrs(MappingRecord record, Set<SubscriberRLOC> subscribers) {
-        Eid eid = record.getEid();
-        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);
-            MappingRecord newRecord = new MappingRecordBuilder(record).setEid(dstAddr).build();
-            handleSmr(newRecord.getEid(), 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;
         }
         final MapRequestBuilder mrb = MapRequestUtil.prepareSMR(eid, LispAddressUtil.toRloc(getLocalAddress()));
         LOG.trace("Built SMR packet: " + mrb.build().toString());
 
-        scheduler = new SmrScheduler();
         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 void removeSubscribers(Eid address) {
-        mapService.removeData(MappingOrigin.Southbound, address, SubKeys.SUBSCRIBERS);
+    private Set<Subscriber> addParentSubscribers(Eid eid, Set<Subscriber> subscribers) {
+        Eid parentPrefix = mapService.getParentPrefix(eid);
+        if (parentPrefix == null) {
+            return subscribers;
+        }
+
+        Set<Subscriber> parentSubscribers = getSubscribers(parentPrefix);
+        if (parentSubscribers != null) {
+            if (subscribers != null) {
+                subscribers.addAll(parentSubscribers);
+            } else {
+                subscribers = parentSubscribers;
+            }
+        }
+        return 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);
     }
 
@@ -268,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;
                 }
@@ -291,7 +334,7 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
 
     @Override
     public void onSmrInvokedReceived(SmrEvent event) {
-        scheduler.smrReceived(event.getSubscriberAddressList());
+        scheduler.smrReceived(event);
     }
 
     /**
@@ -300,53 +343,64 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
      * is triggered.
      */
     private class SmrScheduler {
-        private ScheduledExecutorService executor;
-
-        /**
-         * Scheduling SMRs is done in a single thread. If a use case demands better performance, this may be revisited
-         * and for multi-threading we will need ConcurrentHashMap here along with a multi-threaded executor.
-         */
-        private Map<IpAddressBinary, ScheduledFuture<?>> subscriberFutureMap = new HashMap<>();
-        private long smrNonce;
-
-        void scheduleSmrs(MapRequestBuilder mrb, Iterator<SubscriberRLOC> subscribers) {
-            executor = Executors.newSingleThreadScheduledExecutor();
-            smrNonce = mrb.getNonce();
-
-            // Using Iterator ensures that we don't get a ConcurrentModificationException when removing a SubscriberRLOC
+        final int cpuCores = Runtime.getRuntime().availableProcessors();
+        private final ThreadFactory threadFactory = new ThreadFactoryBuilder()
+                .setNameFormat("smr-executor-%d").build();
+        private final ScheduledExecutorService executor = Executors.newScheduledThreadPool(cpuCores * 2, threadFactory);
+        private final Map<IpAddressBinary, Map<Eid, ScheduledFuture<?>>> subscriberFutureMap = Maps.newConcurrentMap();
+
+        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);
-                    subscriberFutureMap.put(
-                            LispAddressUtil.addressBinaryFromAddress(subscriber.getSrcRloc().getAddress()), future);
+                    final IpAddressBinary subscriberAddress = LispAddressUtil
+                            .addressBinaryFromAddress(subscriber.getSrcRloc().getAddress());
+
+                    if (subscriberFutureMap.containsKey(subscriberAddress)) {
+                        subscriberFutureMap.get(subscriberAddress).put(srcEid, future);
+                    } else {
+                        final Map<Eid, ScheduledFuture<?>> eidFutureMap = Maps.newConcurrentMap();
+                        eidFutureMap.put(srcEid, future);
+                        subscriberFutureMap.put(subscriberAddress, eidFutureMap);
+                    }
                 }
             }
         }
 
-        void smrReceived(List<IpAddressBinary> subscriberAddressList) {
-            ScheduledFuture<?> future;
+        void smrReceived(SmrEvent event) {
+            final List<IpAddressBinary> subscriberAddressList = event.getSubscriberAddressList();
             for (IpAddressBinary subscriberAddress : subscriberAddressList) {
-                future = subscriberFutureMap.get(subscriberAddress);
-                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(), smrNonce);
+                final Map<Eid, ScheduledFuture<?>> eidFutureMap = subscriberFutureMap.get(subscriberAddress);
+                if (eidFutureMap != null) {
+                    final ScheduledFuture<?> future = eidFutureMap.get(event.getEid());
+                    if (future != null && !future.isCancelled()) {
+                        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()) {
+                        subscriberFutureMap.remove(subscriberAddress);
+                    }
                 }
             }
         }
 
         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;
             }
@@ -356,44 +410,55 @@ 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 " + subscriber.getSrcEid(), 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);
-                        subscriberFutureMap.get(subscriberAddress).cancel(false);
+                        cancelAndRemove(subscriberAddress, srcEid);
+                        return;
                     }
                 } catch (Exception e) {
                     LOG.error("Errors encountered while handling SMR:", e);
-                    subscriberFutureMap.get(subscriberAddress).cancel(false);
-                } finally {
-                    tryToShutDownExecutor();
+                    cancelAndRemove(subscriberAddress, srcEid);
+                    return;
                 }
                 executionCount++;
             }
-        }
 
-        private void tryToShutDownExecutor() {
-            if (!executor.isShutdown() && areAllFuturesCanceled()) {
-                executor.shutdown();
-                LOG.trace("SMR scheduler executor shutdown.");
-            }
-        }
+            private void cancelAndRemove(IpAddressBinary subscriberAddress, Eid eid) {
+                final Map<Eid, ScheduledFuture<?>> eidFutureMap = subscriberFutureMap.get(subscriberAddress);
+                if (eidFutureMap == null) {
+                    LOG.warn("Couldn't find subscriber {} in SMR scheduler internal list", subscriberAddress);
+                    return;
+                }
 
-        private boolean areAllFuturesCanceled() {
-            for (Map.Entry<IpAddressBinary, ScheduledFuture<?>> entry : subscriberFutureMap.entrySet()) {
-                if (!entry.getValue().isCancelled()) {
-                    return false;
+                if (eidFutureMap.containsKey(eid)) {
+                    ScheduledFuture<?> eidFuture = eidFutureMap.get(eid);
+                    eidFutureMap.remove(eid);
+                    eidFuture.cancel(false);
+                }
+                if (eidFutureMap.isEmpty()) {
+                    subscriberFutureMap.remove(subscriberAddress);
                 }
             }
-            return true;
         }
     }
 }