Bug 3376: Add debug context for CDS transactions 71/21371/1
authorTom Pantelis <tpanteli@brocade.com>
Wed, 27 May 2015 06:03:20 +0000 (02:03 -0400)
committerMoiz Raja <moraja@cisco.com>
Thu, 28 May 2015 20:57:23 +0000 (20:57 +0000)
Added a new setting, transaction-context-debug-enabled, to the config yang
to enable/disable debug context that outputs the call site trace for
TransactionProxy instances for failed transactions.

Change-Id: I8b1a393871be4fa076054681c62c14fd68dc74b7
Signed-off-by: Tom Pantelis <tpanteli@brocade.com>
(cherry picked from commit 1ae90cd1a9a8000a66942e38a4d1c13d3630c4f8)

opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DatastoreContext.java
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java [new file with mode: 0644]
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBean.java
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/jmx/mbeans/DatastoreConfigurationMXBeanImpl.java
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedConfigDataStoreProviderModule.java
opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/config/yang/config/distributed_datastore_provider/DistributedOperationalDataStoreProviderModule.java
opendaylight/md-sal/sal-distributed-datastore/src/main/yang/distributed-datastore-provider.yang
opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java [new file with mode: 0644]
opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/TransactionProxyTest.java

index 2f323aa..4140d33 100644 (file)
@@ -66,6 +66,7 @@ public class DatastoreContext {
     private int shardBatchedModificationCount = DEFAULT_SHARD_BATCHED_MODIFICATION_COUNT;
     private boolean writeOnlyTransactionOptimizationsEnabled = true;
     private long shardCommitQueueExpiryTimeoutInMillis = DEFAULT_SHARD_COMMIT_QUEUE_EXPIRY_TIMEOUT_IN_MS;
+    private boolean transactionDebugContextEnabled = false;
 
     public static Set<String> getGlobalDatastoreTypes() {
         return globalDatastoreTypes;
@@ -96,6 +97,7 @@ public class DatastoreContext {
         this.shardBatchedModificationCount = other.shardBatchedModificationCount;
         this.writeOnlyTransactionOptimizationsEnabled = other.writeOnlyTransactionOptimizationsEnabled;
         this.shardCommitQueueExpiryTimeoutInMillis = other.shardCommitQueueExpiryTimeoutInMillis;
+        this.transactionDebugContextEnabled = other.transactionDebugContextEnabled;
 
         setShardJournalRecoveryLogBatchSize(other.raftConfig.getJournalRecoveryLogBatchSize());
         setSnapshotBatchCount(other.raftConfig.getSnapshotBatchCount());
@@ -208,6 +210,10 @@ public class DatastoreContext {
         return shardCommitQueueExpiryTimeoutInMillis;
     }
 
+    public boolean isTransactionDebugContextEnabled() {
+        return transactionDebugContextEnabled;
+    }
+
     public static class Builder {
         private final DatastoreContext datastoreContext;
         private int maxShardDataChangeExecutorPoolSize =
@@ -364,6 +370,11 @@ public class DatastoreContext {
             return this;
         }
 
+        public Builder transactionDebugContextEnabled(boolean value) {
+            datastoreContext.transactionDebugContextEnabled = value;
+            return this;
+        }
+
         public Builder maxShardDataChangeExecutorPoolSize(int maxShardDataChangeExecutorPoolSize) {
             this.maxShardDataChangeExecutorPoolSize = maxShardDataChangeExecutorPoolSize;
             return this;
diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohort.java
new file mode 100644 (file)
index 0000000..9a15de8
--- /dev/null
@@ -0,0 +1,89 @@
+/*
+ * Copyright (c) 2015 Brocade Communications Systems, 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,
+ * and is available at http://www.eclipse.org/legal/epl-v10.html
+ */
+package org.opendaylight.controller.cluster.datastore;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Preconditions;
+import com.google.common.util.concurrent.FutureCallback;
+import com.google.common.util.concurrent.Futures;
+import com.google.common.util.concurrent.ListenableFuture;
+import java.util.List;
+import org.opendaylight.controller.cluster.datastore.identifiers.TransactionIdentifier;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import scala.concurrent.Future;
+
+/**
+ * An AbstractThreePhaseCommitCohort implementation used for debugging. If a failure occurs, the transaction
+ * call site is printed.
+ *
+ * @author Thomas Pantelis
+ */
+class DebugThreePhaseCommitCohort extends AbstractThreePhaseCommitCohort<Object> {
+    private static final Logger LOG = LoggerFactory.getLogger(DebugThreePhaseCommitCohort.class);
+
+    private final AbstractThreePhaseCommitCohort<?> delegate;
+    private final Throwable debugContext;
+    private final TransactionIdentifier transactionId;
+    private Logger log = LOG;
+
+    DebugThreePhaseCommitCohort(TransactionIdentifier transactionId, AbstractThreePhaseCommitCohort<?> delegate,
+            Throwable debugContext) {
+        this.delegate = Preconditions.checkNotNull(delegate);
+        this.debugContext = Preconditions.checkNotNull(debugContext);
+        this.transactionId = Preconditions.checkNotNull(transactionId);
+    }
+
+    private <V> ListenableFuture<V> addFutureCallback(ListenableFuture<V> future) {
+        Futures.addCallback(future, new FutureCallback<V>() {
+            @Override
+            public void onSuccess(V result) {
+                // no-op
+            }
+
+            @Override
+            public void onFailure(Throwable t) {
+                log.warn("Transaction {} failed with error \"{}\" - was allocated in the following context",
+                        transactionId, t, debugContext);
+            }
+        });
+
+        return future;
+    }
+
+    @Override
+    public ListenableFuture<Boolean> canCommit() {
+        return addFutureCallback(delegate.canCommit());
+    }
+
+    @Override
+    public ListenableFuture<Void> preCommit() {
+        return addFutureCallback(delegate.preCommit());
+    }
+
+    @Override
+    public ListenableFuture<Void> commit() {
+        return addFutureCallback(delegate.commit());
+    }
+
+    @Override
+    public ListenableFuture<Void> abort() {
+        return delegate.abort();
+    }
+
+    @SuppressWarnings({ "rawtypes", "unchecked" })
+    @Override
+    List<Future<Object>> getCohortFutures() {
+        return ((AbstractThreePhaseCommitCohort)delegate).getCohortFutures();
+    }
+
+    @VisibleForTesting
+    void setLogger(Logger log) {
+        this.log = log;
+    }
+}
index eca930a..e7a0004 100644 (file)
@@ -62,7 +62,8 @@ public class TransactionProxy extends AbstractDOMStoreTransaction<TransactionIde
 
     @VisibleForTesting
     public TransactionProxy(final AbstractTransactionContextFactory<?> txContextFactory, final TransactionType type) {
-        super(txContextFactory.nextIdentifier(), false);
+        super(txContextFactory.nextIdentifier(), txContextFactory.getActorContext().getDatastoreContext()
+                .isTransactionDebugContextEnabled());
         this.txContextFactory = txContextFactory;
         this.type = Preconditions.checkNotNull(type);
 
@@ -255,7 +256,9 @@ public class TransactionProxy extends AbstractDOMStoreTransaction<TransactionIde
         }
 
         txContextFactory.onTransactionReady(getIdentifier(), ret.getCohortFutures());
-        return ret;
+
+        final Throwable debugContext = getDebugContext();
+        return debugContext == null ? ret : new DebugThreePhaseCommitCohort(getIdentifier(), ret, debugContext);
     }
 
     private AbstractThreePhaseCommitCohort<?> createSingleCommitCohort(final String shardName,
index 261b93d..b5f01ae 100644 (file)
@@ -104,6 +104,11 @@ public class DatastoreConfigurationMXBeanImpl extends AbstractMXBean implements
         return context.getTransactionCreationInitialRateLimit();
     }
 
+    @Override
+    public boolean getTransactionContextDebugEnabled() {
+        return context.isTransactionDebugContextEnabled();
+    }
+
     @Override
     public int getMaxShardDataChangeExecutorPoolSize() {
         return context.getDataStoreProperties().getMaxDataChangeExecutorPoolSize();
index 539797e..cd27d1d 100644 (file)
@@ -66,6 +66,7 @@ public class DistributedConfigDataStoreProviderModule extends
                 .shardBatchedModificationCount(props.getShardBatchedModificationCount().getValue().intValue())
                 .shardCommitQueueExpiryTimeoutInSeconds(
                         props.getShardCommitQueueExpiryTimeoutInSeconds().getValue().intValue())
+                .transactionDebugContextEnabled(props.getTransactionDebugContextEnabled())
                 .build();
 
         return DistributedDataStoreFactory.createInstance(getConfigSchemaServiceDependency(),
index 45ed184..1c94acf 100644 (file)
@@ -67,6 +67,7 @@ public class DistributedOperationalDataStoreProviderModule extends
                 .shardBatchedModificationCount(props.getShardBatchedModificationCount().getValue().intValue())
                 .shardCommitQueueExpiryTimeoutInSeconds(
                         props.getShardCommitQueueExpiryTimeoutInSeconds().getValue().intValue())
+                .transactionDebugContextEnabled(props.getTransactionDebugContextEnabled())
                 .build();
 
         return DistributedDataStoreFactory.createInstance(getOperationalSchemaServiceDependency(),
index 3c753d0..09125f1 100644 (file)
@@ -193,20 +193,27 @@ module distributed-datastore-provider {
             description "Enable or disable data persistence";
          }
 
-        leaf shard-isolated-leader-check-interval-in-millis {
+         leaf shard-isolated-leader-check-interval-in-millis {
             default 5000;
             type heartbeat-interval-type;
             description "The interval at which the leader of the shard will check if its majority
                         followers are active and term itself as isolated";
-        }
+         }
 
-        leaf transaction-creation-initial-rate-limit {
+         leaf transaction-creation-initial-rate-limit {
             default 100;
             type non-zero-uint32-type;
             description "The initial number of transactions per second that are allowed before the data store
                          should begin applying back pressure. This number is only used as an initial guidance,
                          subsequently the datastore measures the latency for a commit and auto-adjusts the rate limit";
-        }
+         }
+         
+         leaf transaction-debug-context-enabled {
+             default false;
+             type boolean;
+             description "Enable or disable transaction context debug. This will log the call site trace for
+                          transactions that fail";
+         }
     }
 
     // Augments the 'configuration' choice node under modules/module.
diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java b/opendaylight/md-sal/sal-distributed-datastore/src/test/java/org/opendaylight/controller/cluster/datastore/DebugThreePhaseCommitCohortTest.java
new file mode 100644 (file)
index 0000000..4427ee8
--- /dev/null
@@ -0,0 +1,80 @@
+/*
+ * Copyright (c) 2015 Brocade Communications Systems, 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,
+ * and is available at http://www.eclipse.org/legal/epl-v10.html
+ */
+package org.opendaylight.controller.cluster.datastore;
+
+import static org.junit.Assert.assertSame;
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.anyString;
+import static org.mockito.Matchers.same;
+import static org.mockito.Mockito.doReturn;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.never;
+import static org.mockito.Mockito.reset;
+import static org.mockito.Mockito.verify;
+import com.google.common.util.concurrent.Futures;
+import com.google.common.util.concurrent.ListenableFuture;
+import java.util.ArrayList;
+import java.util.List;
+import org.junit.Test;
+import org.opendaylight.controller.cluster.datastore.identifiers.TransactionIdentifier;
+import org.slf4j.Logger;
+import scala.concurrent.Future;
+
+/**
+ * Unit tests for DebugThreePhaseCommitCohort.
+ *
+ * @author Thomas Pantelis
+ */
+public class DebugThreePhaseCommitCohortTest {
+
+    @Test
+    public void test() {
+        AbstractThreePhaseCommitCohort<?> mockDelegate = mock(AbstractThreePhaseCommitCohort.class);
+        Exception failure = new Exception("mock failure");
+        ListenableFuture<Object> expFailedFuture = Futures.immediateFailedFuture(failure);
+        doReturn(expFailedFuture).when(mockDelegate).canCommit();
+        doReturn(expFailedFuture).when(mockDelegate).preCommit();
+        doReturn(expFailedFuture).when(mockDelegate).commit();
+
+        ListenableFuture<Object> expAbortFuture = Futures.immediateFuture(null);
+        doReturn(expAbortFuture).when(mockDelegate).abort();
+
+        List<Future<Object>> expCohortFutures = new ArrayList<>();
+        doReturn(expCohortFutures).when(mockDelegate).getCohortFutures();
+
+        TransactionIdentifier transactionId = TransactionIdentifier.create("1", 1, "");
+        Throwable debugContext = new RuntimeException("mock");
+        DebugThreePhaseCommitCohort cohort = new DebugThreePhaseCommitCohort(transactionId , mockDelegate , debugContext );
+
+        Logger mockLogger = mock(Logger.class);
+        cohort.setLogger(mockLogger);
+
+        assertSame("canCommit", expFailedFuture, cohort.canCommit());
+        verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext));
+
+        reset(mockLogger);
+        assertSame("preCommit", expFailedFuture, cohort.preCommit());
+        verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext));
+
+        reset(mockLogger);
+        assertSame("commit", expFailedFuture, cohort.commit());
+        verify(mockLogger).warn(anyString(), same(transactionId), same(failure), same(debugContext));
+
+        assertSame("abort", expAbortFuture, cohort.abort());
+
+        assertSame("getCohortFutures", expCohortFutures, cohort.getCohortFutures());
+
+        reset(mockLogger);
+        ListenableFuture<Boolean> expSuccessFuture = Futures.immediateFuture(Boolean.TRUE);
+        doReturn(expSuccessFuture).when(mockDelegate).canCommit();
+
+        assertSame("canCommit", expSuccessFuture, cohort.canCommit());
+        verify(mockLogger, never()).warn(anyString(), any(TransactionIdentifier.class), any(Throwable.class),
+                any(Throwable.class));
+    }
+}
index f19bace..8909e1d 100644 (file)
@@ -615,6 +615,25 @@ public class TransactionProxyTest extends AbstractTransactionProxyTest {
         verifyCohortFutures((SingleCommitCohortProxy)ready, TestException.class);
     }
 
+    @Test
+    public void testReadyWithDebugContextEnabled() throws Exception {
+        dataStoreContextBuilder.transactionDebugContextEnabled(true);
+
+        ActorRef actorRef = setupActorContextWithInitialCreateTransaction(getSystem(), READ_WRITE);
+
+        expectBatchedModificationsReady(actorRef, true);
+
+        TransactionProxy transactionProxy = new TransactionProxy(mockComponentFactory, READ_WRITE);
+
+        transactionProxy.merge(TestModel.TEST_PATH, ImmutableNodes.containerNode(TestModel.TEST_QNAME));
+
+        DOMStoreThreePhaseCommitCohort ready = transactionProxy.ready();
+
+        assertTrue(ready instanceof DebugThreePhaseCommitCohort);
+
+        verifyCohortFutures((DebugThreePhaseCommitCohort)ready, new CommitTransactionReply().toSerializable());
+    }
+
     private void testWriteOnlyTxWithFindPrimaryShardFailure(Exception toThrow) throws Exception {
         doReturn(Futures.failed(toThrow)).when(mockActorContext).findPrimaryShardAsync(anyString());