Bug 3376: Add debug context for CDS transactions 26/21226/4
authorTom Pantelis <tpanteli@brocade.com>
Wed, 27 May 2015 06:03:20 +0000 (02:03 -0400)
committerGerrit Code Review <gerrit@opendaylight.org>
Thu, 28 May 2015 20:57:06 +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>
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 2f323aafd35694b0d9c496d9eed58742a10b1aaa..4140d3323b33be4955b720eb8238644ebb3f305e 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 eca930a03d89c3533f59dd441257197357b93bb4..e7a00042e4146c5ddc03a013e6eeda3198a38ea3 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 981be366d09cb15ca18840021a4a9d8d2948b028..daf006c3d694195084c2567f77931fbc7bbb1cd3 100644 (file)
@@ -44,6 +44,8 @@ public interface DatastoreConfigurationMXBean {
 
     long getTransactionCreationInitialRateLimit();
 
+    boolean getTransactionContextDebugEnabled();
+
     int getMaxShardDataChangeExecutorPoolSize();
 
     int getMaxShardDataChangeExecutorQueueSize();
index 261b93de56e057874a44600495e977d73b643bd4..b5f01aeedfadf3492ca282030e1ab864c16da557 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 539797e65966e9d8dcdfbef11969223f8308f267..cd27d1df7944d43f6bbd8e44223513cc7f4d044f 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 45ed184de3875feb96486bb71b2bd952df139fd8..1c94acfca121f9feba27e8e95a101c520b2a9a64 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 3c753d02d5a9520d7ca82db1a4a7d90217c9d222..09125f1b5959500e9953f57ad911e54e495fd288 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 f19bace5b99ce21862a04455241cf913a34fc350..8909e1d3127fe7e49e986470f95d4a04533cf206 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());