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>

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());
             }
 
                         .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(
             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(
 
         } 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 3fdc446542a2ab811e25c823d35ba8a814a0d103..0f7e4a31c9da74f4c9f0716344d1c72b6e6b12e5 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;
 
 
 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 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.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.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 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;
 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 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 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) {
 
     @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 {
                 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 {
                     LOG.trace("Ignored notification content: {}", change);
                 }
             } else {


@@ -72,6 +84,11 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
         return localCopy.equals(expected);
     }
 
         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();
     public Future<Void> tryFinishProcessing() {
         executorService = Executors.newSingleThreadScheduledExecutor();
         final SettableFuture<Void> settableFuture = SettableFuture.create();


@@ -81,6 +98,44 @@ public class IdIntsListener implements ClusteredDOMDataTreeChangeListener {
         return settableFuture;
     }
 
         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;
     private class CheckFinishedTask implements Runnable {
 
         private final SettableFuture<Void> future;