From: Tom Pantelis Date: Fri, 30 Nov 2018 16:43:18 +0000 (-0500) Subject: Improve failure reporting in IdIntsListener X-Git-Tag: release/neon~53 X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=commitdiff_plain;h=95788d18b61dd21bdd8406a9c725ad76b3044535 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 --- 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 4198441329..92bacd1f89 100644 --- 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 3fdc446542..0f7e4a31c9 100644 --- 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 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 tryFinishProcessing() { executorService = Executors.newSingleThreadScheduledExecutor(); final SettableFuture 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 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 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 future;