Improve failure reporting in IdIntsListener

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>
(cherry picked from commit 95788d18b61dd21bdd8406a9c725ad76b3044535)

diff --git a/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/MdsalLowLevelTestProvider.java b/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/MdsalLowLevelTestProvider.java
index 4198441329ce5635c1a0b369215671c13c7c6d67..92bacd1f89aacfdd67b12dfd299dce3fdaed64ab 100644 (file)
--- a/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/MdsalLowLevelTestProvider.java
+++ b/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/MdsalLowLevelTestProvider.java
@@ -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(

diff --git a/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/impl/IdIntsListener.java b/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/impl/IdIntsListener.java
index 3e644393f163975fb13ab220da40b2e80ab00fda..ed93b380e3f31fc060e1d599e7814879b791f1ee 100644 (file)
--- a/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/impl/IdIntsListener.java
+++ b/opendaylight/md-sal/samples/clustering-test-app/provider/src/main/java/org/opendaylight/controller/clustering/it/provider/impl/IdIntsListener.java
@@ -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;