Improve failure reporting in IdIntsListener 23/78323/2
authorTom Pantelis <tompantelis@gmail.com>
Fri, 30 Nov 2018 16:43:18 +0000 (11:43 -0500)
committerTom Pantelis <tompantelis@gmail.com>
Fri, 30 Nov 2018 17:37:24 +0000 (12:37 -0500)
The Listener Stability CSIT fails intermittently where the
IdIntsListener reports that the final read of the data doesn't
match it's local copy obtained from DTCN's. It would be helpful
to output the difference.

When the test fails, there are a lot of "Ignoring notification"
warnings from IdIntsListener so output the diff the first time
that occurs.

Change-Id: I49e9cd0414a904a61778a8c028ead7dc2b8fd593
Signed-off-by: Tom Pantelis <tompantelis@gmail.com>
opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/MdsalLowLevelTestProvider.java
opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/impl/IdIntsListener.java

index 4198441..92bacd1 100644 (file)
@@ -556,9 +556,14 @@ public class MdsalLowLevelTestProvider implements OdlMdsalLowlevelControlService
                         .withRpcError(error).build());
             }
 
+            final boolean nodesEqual = idIntsListener.checkEqual(readResult.get());
+            if (!nodesEqual) {
+                LOG.error("Final read of id-int does not match IdIntsListener's copy. {}",
+                        idIntsListener.diffWithLocalCopy(readResult.get()));
+            }
+
             return Futures.immediateFuture(
-                    RpcResultBuilder.success(new UnsubscribeDtclOutputBuilder()
-                            .setCopyMatches(idIntsListener.checkEqual(readResult.get()))).build());
+                    RpcResultBuilder.success(new UnsubscribeDtclOutputBuilder().setCopyMatches(nodesEqual)).build());
 
         } catch (final InterruptedException | ExecutionException e) {
             final RpcError error = RpcResultBuilder.newError(
index 3fdc446..0f7e4a3 100644 (file)
@@ -8,17 +8,27 @@
 
 package org.opendaylight.controller.clustering.it.provider.impl;
 
+import static org.opendaylight.controller.clustering.it.provider.impl.AbstractTransactionHandler.ITEM;
+
 import com.google.common.base.Preconditions;
 import com.google.common.util.concurrent.SettableFuture;
+import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
 import java.util.Collection;
+import java.util.HashMap;
+import java.util.Map;
 import java.util.concurrent.Executors;
 import java.util.concurrent.Future;
 import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.ScheduledFuture;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicLong;
 import javax.annotation.Nonnull;
 import org.opendaylight.controller.md.sal.dom.api.ClusteredDOMDataTreeChangeListener;
+import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier;
+import org.opendaylight.yangtools.yang.data.api.YangInstanceIdentifier.NodeIdentifierWithPredicates;
+import org.opendaylight.yangtools.yang.data.api.schema.MapEntryNode;
+import org.opendaylight.yangtools.yang.data.api.schema.MapNode;
 import org.opendaylight.yangtools.yang.data.api.schema.NormalizedNode;
 import org.opendaylight.yangtools.yang.data.api.schema.tree.DataTreeCandidate;
 import org.slf4j.Logger;
@@ -29,10 +39,11 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
     private static final Logger LOG = LoggerFactory.getLogger(IdIntsListener.class);
     private static final long SECOND_AS_NANO = 1000000000;
 
-    private NormalizedNode<?, ?> localCopy = null;
+    private volatile NormalizedNode<?, ?> localCopy;
     private final AtomicLong lastNotifTimestamp = new AtomicLong(0);
     private ScheduledExecutorService executorService;
     private ScheduledFuture<?> scheduledFuture;
+    private final AtomicBoolean loggedIgnoredNotificationDiff = new AtomicBoolean();
 
     @Override
     public void onDataTreeChanged(@Nonnull final Collection<DataTreeCandidate> changes) {
@@ -55,7 +66,8 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
                 if (localCopy == null || checkEqual(change.getRootNode().getDataBefore().get())) {
                     localCopy = change.getRootNode().getDataAfter().get();
                 } else {
-                    LOG.warn("Ignoring notification.");
+                    LOG.warn("Ignoring notification {}", loggedIgnoredNotificationDiff.compareAndSet(false, true)
+                        ? diffWithLocalCopy(change.getRootNode().getDataBefore().get()) : "");
                     LOG.trace("Ignored notification content: {}", change);
                 }
             } else {
@@ -72,6 +84,11 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
         return localCopy.equals(expected);
     }
 
+    @SuppressFBWarnings("BC_UNCONFIRMED_CAST")
+    public String diffWithLocalCopy(final NormalizedNode<?, ?> expected) {
+        return diffNodes((MapNode)expected, (MapNode)localCopy);
+    }
+
     public Future<Void> tryFinishProcessing() {
         executorService = Executors.newSingleThreadScheduledExecutor();
         final SettableFuture<Void> settableFuture = SettableFuture.create();
@@ -81,6 +98,44 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
         return settableFuture;
     }
 
+    public static String diffNodes(final MapNode expected, final MapNode actual) {
+        StringBuilder builder = new StringBuilder("MapNodes diff:");
+
+        final YangInstanceIdentifier.NodeIdentifier itemNodeId = new YangInstanceIdentifier.NodeIdentifier(ITEM);
+
+        Map<NodeIdentifierWithPredicates, MapEntryNode> expIdIntMap = new HashMap<>();
+        expected.getValue().forEach(node -> expIdIntMap.put(node.getIdentifier(), node));
+
+        actual.getValue().forEach(actIdInt -> {
+            final MapEntryNode expIdInt = expIdIntMap.remove(actIdInt.getIdentifier());
+            if (expIdInt == null) {
+                builder.append('\n').append("  Unexpected id-int entry for ").append(actIdInt.getIdentifier());
+                return;
+            }
+
+            Map<NodeIdentifierWithPredicates, MapEntryNode> expItemMap = new HashMap<>();
+            ((MapNode)expIdInt.getChild(itemNodeId).get()).getValue()
+                .forEach(node -> expItemMap.put(node.getIdentifier(), node));
+
+            ((MapNode)actIdInt.getChild(itemNodeId).get()).getValue().forEach(actItem -> {
+                final MapEntryNode expItem = expItemMap.remove(actItem.getIdentifier());
+                if (expItem == null) {
+                    builder.append('\n').append("  Unexpected item entry ").append(actItem.getIdentifier())
+                        .append(" for id-int entry ").append(actIdInt.getIdentifier());
+                }
+            });
+
+            expItemMap.values().forEach(node -> builder.append('\n')
+                .append("  Actual is missing item entry ").append(node.getIdentifier())
+                    .append(" for id-int entry ").append(actIdInt.getIdentifier()));
+        });
+
+        expIdIntMap.values().forEach(node -> builder.append('\n')
+            .append("  Actual is missing id-int entry for ").append(node.getIdentifier()));
+
+        return builder.toString();
+    }
+
     private class CheckFinishedTask implements Runnable {
 
         private final SettableFuture<Void> future;

©2013 OpenDaylight, A Linux Foundation Collaborative Project. All Rights Reserved.
OpenDaylight is a registered trademark of The OpenDaylight Project, Inc.
Linux Foundation and OpenDaylight are registered trademarks of the Linux Foundation.
Linux is a registered trademark of Linus Torvalds.