[ONOS-6425] Improve logging for transactions
Change-Id: I74ff83a96aa76782a724d9db3e1a9557a02bacf5
diff --git a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/DefaultTransactionContext.java b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/DefaultTransactionContext.java
index 2f3fe11..34ffad7 100644
--- a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/DefaultTransactionContext.java
+++ b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/DefaultTransactionContext.java
@@ -24,14 +24,17 @@
import org.onosproject.store.service.TransactionContext;
import org.onosproject.store.service.TransactionalMap;
import org.onosproject.utils.MeteringAgent;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import static com.google.common.base.MoreObjects.toStringHelper;
+import static com.google.common.base.Preconditions.checkState;
/**
* Default implementation of transaction context.
*/
public class DefaultTransactionContext implements TransactionContext {
-
+ private final Logger log = LoggerFactory.getLogger(getClass());
private final AtomicBoolean isOpen = new AtomicBoolean(false);
private final TransactionId transactionId;
private final TransactionCoordinator transactionCoordinator;
@@ -60,20 +63,26 @@
@Override
public void begin() {
- if (!isOpen.compareAndSet(false, true)) {
+ if (isOpen.compareAndSet(false, true)) {
+ log.trace("Opened transaction {}", transactionId);
+ } else {
throw new IllegalStateException("TransactionContext is already open");
}
}
@Override
public CompletableFuture<CommitStatus> commit() {
+ checkState(isOpen.get(), "Transaction not open");
final MeteringAgent.Context timer = monitor.startTimer("commit");
+ log.debug("Committing transaction {}", transactionId);
return transactionCoordinator.commit().whenComplete((r, e) -> timer.stop(e));
}
@Override
public void abort() {
- isOpen.set(false);
+ if (isOpen.compareAndSet(true, false)) {
+ log.debug("Aborted transaction {}", transactionId);
+ }
}
@Override
diff --git a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/Transaction.java b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/Transaction.java
index 8ad8cb8..0e2e45d 100644
--- a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/Transaction.java
+++ b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/Transaction.java
@@ -25,6 +25,8 @@
import org.onosproject.store.service.Version;
import org.onosproject.store.service.TransactionContext;
import org.onosproject.store.service.TransactionException;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import static com.google.common.base.MoreObjects.toStringHelper;
import static com.google.common.base.Preconditions.checkState;
@@ -105,6 +107,7 @@
private static final String TX_INACTIVE_ERROR = "transaction is not active";
private static final String TX_UNPREPARED_ERROR = "transaction has not been prepared";
+ protected final Logger log = LoggerFactory.getLogger(getClass());
protected final TransactionId transactionId;
protected final Transactional<T> transactionalObject;
private final AtomicBoolean open = new AtomicBoolean();
@@ -191,9 +194,11 @@
* @return a completable future to be completed once the transaction has been started
*/
public CompletableFuture<Version> begin() {
+ log.debug("Beginning transaction {} for {}", transactionId, transactionalObject);
open();
return transactionalObject.begin(transactionId).thenApply(lock -> {
this.lock = lock;
+ log.trace("Transaction lock acquired: {}", lock);
return lock;
});
}
@@ -212,6 +217,7 @@
public CompletableFuture<Boolean> prepare(List<T> updates) {
checkOpen();
checkActive();
+ log.debug("Preparing transaction {} for {}", transactionId, transactionalObject);
Version lock = this.lock;
checkState(lock != null, TX_INACTIVE_ERROR);
setState(State.PREPARING);
@@ -234,6 +240,7 @@
public CompletableFuture<Boolean> prepareAndCommit(List<T> updates) {
checkOpen();
checkActive();
+ log.debug("Preparing and committing transaction {} for {}", transactionId, transactionalObject);
Version lock = this.lock;
checkState(lock != null, TX_INACTIVE_ERROR);
setState(State.PREPARING);
@@ -255,6 +262,7 @@
public CompletableFuture<Void> commit() {
checkOpen();
checkPrepared();
+ log.debug("Committing transaction {} for {}", transactionId, transactionalObject);
setState(State.COMMITTING);
return transactionalObject.commit(transactionId).thenRun(() -> {
setState(State.COMMITTED);
@@ -271,6 +279,7 @@
public CompletableFuture<Void> rollback() {
checkOpen();
checkPrepared();
+ log.debug("Rolling back transaction {} for {}", transactionId, transactionalObject);
setState(State.ROLLING_BACK);
return transactionalObject.rollback(transactionId).thenRun(() -> {
setState(State.ROLLED_BACK);
diff --git a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/TransactionCoordinator.java b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/TransactionCoordinator.java
index 9826266..4f5f7cd 100644
--- a/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/TransactionCoordinator.java
+++ b/core/store/primitives/src/main/java/org/onosproject/store/primitives/impl/TransactionCoordinator.java
@@ -25,6 +25,8 @@
import org.onosproject.store.service.CommitStatus;
import org.onosproject.store.service.Serializer;
import org.onosproject.store.service.TransactionalMap;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import static com.google.common.base.MoreObjects.toStringHelper;
@@ -32,6 +34,7 @@
* Transaction coordinator.
*/
public class TransactionCoordinator {
+ private final Logger log = LoggerFactory.getLogger(getClass());
protected final TransactionId transactionId;
protected final TransactionManager transactionManager;
protected final Set<TransactionParticipant> transactionParticipants = Sets.newConcurrentHashSet();
@@ -67,8 +70,10 @@
.count();
if (totalParticipants == 0) {
+ log.debug("No transaction participants, skipping commit", totalParticipants);
return CompletableFuture.completedFuture(CommitStatus.SUCCESS);
} else if (totalParticipants == 1) {
+ log.debug("Committing transaction {} via 1 participant", transactionId);
return transactionParticipants.stream()
.filter(TransactionParticipant::hasPendingUpdates)
.findFirst()
@@ -76,6 +81,7 @@
.prepareAndCommit()
.thenApply(v -> v ? CommitStatus.SUCCESS : CommitStatus.FAILURE);
} else {
+ log.debug("Committing transaction {} via {} participants", transactionId, totalParticipants);
Set<TransactionParticipant> transactionParticipants = this.transactionParticipants.stream()
.filter(TransactionParticipant::hasPendingUpdates)
.collect(Collectors.toSet());
@@ -101,6 +107,7 @@
* @return a completable future indicating whether <em>all</em> prepares succeeded
*/
protected CompletableFuture<Boolean> prepare(Set<TransactionParticipant> transactionParticipants) {
+ log.trace("Preparing transaction {} via {}", transactionId, transactionParticipants);
return Tools.allOf(transactionParticipants.stream()
.map(TransactionParticipant::prepare)
.collect(Collectors.toList()))
@@ -114,6 +121,7 @@
* @return a completable future to be completed once the commits are complete
*/
protected CompletableFuture<Void> commit(Set<TransactionParticipant> transactionParticipants) {
+ log.trace("Committing transaction {} via {}", transactionId, transactionParticipants);
return CompletableFuture.allOf(transactionParticipants.stream()
.map(TransactionParticipant::commit)
.toArray(CompletableFuture[]::new));
@@ -126,6 +134,7 @@
* @return a completable future to be completed once the rollbacks are complete
*/
protected CompletableFuture<Void> rollback(Set<TransactionParticipant> transactionParticipants) {
+ log.trace("Rolling back transaction {} via {}", transactionId, transactionParticipants);
return CompletableFuture.allOf(transactionParticipants.stream()
.map(TransactionParticipant::rollback)
.toArray(CompletableFuture[]::new));