QPID-3017: improve error handling for the new transaction classes, add some logging, add unit tests

Applied patches from Keith Wall


git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk@1064629 13f79535-47bb-0310-9956-ffa450edef68

4 files changed, 274 insertions, 123 deletions

diff --git a/qpid/java/broker/src/main/java/org/apache/qpid/server/AMQChannel.java b/qpid/java/broker/src/main/java/org/apache/qpid/server/AMQChannel.java
index 3e31115dcb..4f86c82578 100644
--- a/qpid/java/broker/src/main/java/org/apache/qpid/server/AMQChannel.java
+++ b/qpid/java/broker/src/main/java/org/apache/qpid/server/AMQChannel.java
@@ -281,7 +281,7 @@ public class AMQChannel implements SessionConfig, AMQSessionModel
             routeCurrentMessage();
 
 
-            _transaction.addPostCommitAction(new ServerTransaction.Action()
+            _transaction.addPostTransactionAction(new ServerTransaction.Action()
             {
 
                 public void postCommit()
@@ -313,7 +313,7 @@ public class AMQChannel implements SessionConfig, AMQSessionModel
 
                 if(!checkMessageUserId(_currentMessage.getContentHeader()))
                 {
-                    _transaction.addPostCommitAction(new WriteReturnAction(AMQConstant.ACCESS_REFUSED, "Access Refused", _currentMessage));
+                    _transaction.addPostTransactionAction(new WriteReturnAction(AMQConstant.ACCESS_REFUSED, "Access Refused", _currentMessage));
                 }
                 else
                 {
@@ -321,7 +321,7 @@ public class AMQChannel implements SessionConfig, AMQSessionModel
                     {
                         if (_currentMessage.isMandatory() || _currentMessage.isImmediate())
                         {
-                            _transaction.addPostCommitAction(new WriteReturnAction(AMQConstant.NO_ROUTE, "No Route for message", _currentMessage));
+                            _transaction.addPostTransactionAction(new WriteReturnAction(AMQConstant.NO_ROUTE, "No Route for message", _currentMessage));
                         }
                         else
                         {
diff --git a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/AutoCommitTransaction.java b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/AutoCommitTransaction.java
index f674741057..db781ead96 100755
--- a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/AutoCommitTransaction.java
+++ b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/AutoCommitTransaction.java
@@ -20,19 +20,28 @@
  */
 package org.apache.qpid.server.txn;
 
-import org.apache.qpid.server.queue.AMQQueue;
-import org.apache.qpid.server.queue.QueueEntry;
-import org.apache.qpid.server.queue.BaseQueue;
+import java.util.Collection;
+import java.util.List;
+
+import org.apache.log4j.Logger;
+import org.apache.qpid.AMQException;
+import org.apache.qpid.AMQStoreException;
 import org.apache.qpid.server.message.EnqueableMessage;
 import org.apache.qpid.server.message.ServerMessage;
+import org.apache.qpid.server.queue.BaseQueue;
+import org.apache.qpid.server.queue.QueueEntry;
 import org.apache.qpid.server.store.TransactionLog;
-import org.apache.qpid.AMQException;
-
-import java.util.List;
-import java.util.Collection;
 
+/**
+ * An implementation of ServerTransaction where each enqueue/dequeue
+ * operation takes place within it own transaction.
+ * 
+ * Since there is no long-lived transaction, the commit and rollback methods of
+ * this implementation are empty.
+ */
 public class AutoCommitTransaction implements ServerTransaction
 {
+    protected static final Logger _logger = Logger.getLogger(AutoCommitTransaction.class);
 
     private final TransactionLog _transactionLog;
 
@@ -41,52 +50,69 @@ public class AutoCommitTransaction implements ServerTransaction
         _transactionLog = transactionLog;
     }
 
-
-    public void addPostCommitAction(Action postCommitAction)
+    /**
+     * Since AutoCommitTransaction have no concept of a long lived transaction, any Actions registered
+     * by the caller are executed immediately.
+     */
+    public void addPostTransactionAction(Action immediateAction)
     {
-        postCommitAction.postCommit();
+        immediateAction.postCommit();
     }
 
-    public void dequeue(BaseQueue queue, EnqueableMessage message, Action postCommitAction)
+    public void dequeue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction)
     {
-
+        TransactionLog.Transaction txn = null;
         try
         {
             if(message.isPersistent() && queue.isDurable())
             {
+                if (_logger.isDebugEnabled())
+                {
+                    _logger.debug("Dequeue of message number " + message.getMessageNumber() + " from transaction log. Queue : " + queue.getNameShortString());
+                }
 
-                TransactionLog.Transaction txn = _transactionLog.newTransaction();
+                txn = _transactionLog.newTransaction();
                 txn.dequeueMessage(queue, message.getMessageNumber());
-                // store.remove enqueue
-                // store.commit
                 txn.commitTran();
+                txn = null;
             }
-            postCommitAction.postCommit();
+            postTransactionAction.postCommit();
+            postTransactionAction = null;
         }
         catch (AMQException e)
         {
-            //TODO
-            postCommitAction.onRollback();
-            throw new RuntimeException(e);
+            _logger.error("Error during message dequeue", e);
+            throw new RuntimeException("Error during message dequeue", e);
+        }
+        finally
+        {
+            rollbackIfNecessary(postTransactionAction, txn);
         }
+
     }
 
-    public void dequeue(Collection<QueueEntry> ackedMessages, Action postCommitAction)
+    public void dequeue(Collection<QueueEntry> queueEntries, Action postTransactionAction)
     {
+        TransactionLog.Transaction txn = null;
         try
         {
-            TransactionLog.Transaction txn = null;
-            for(QueueEntry entry : ackedMessages)
+            for(QueueEntry entry : queueEntries)
             {
                 ServerMessage message = entry.getMessage();
-                AMQQueue queue = entry.getQueue();
+                BaseQueue queue = entry.getQueue();
 
                 if(message.isPersistent() && queue.isDurable())
                 {
+                    if (_logger.isDebugEnabled())
+                    {
+                        _logger.debug("Dequeue of message number " + message.getMessageNumber() + " from transaction log. Queue : " + queue.getNameShortString());
+                    }
+
                     if(txn == null)
                     {
                         txn = _transactionLog.newTransaction();
                     }
+
                     txn.dequeueMessage(queue, message.getMessageNumber());
                 }
 
@@ -94,78 +120,134 @@ public class AutoCommitTransaction implements ServerTransaction
             if(txn != null)
             {
                 txn.commitTran();
+                txn = null;
             }
-            postCommitAction.postCommit();
+            postTransactionAction.postCommit();
+            postTransactionAction = null;
         }
         catch (AMQException e)
         {
-            //TODO
-            postCommitAction.onRollback();
-            throw new RuntimeException(e);
+            _logger.error("Error during message dequeues", e);
+            throw new RuntimeException("Error during message dequeues", e);
+        }
+        finally
+        {
+            rollbackIfNecessary(postTransactionAction, txn);
         }
+
     }
 
 
-    public void enqueue(BaseQueue queue, EnqueableMessage message, Action postCommitAction)
+    public void enqueue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction)
     {
+        TransactionLog.Transaction txn = null;
         try
         {
             if(message.isPersistent() && queue.isDurable())
             {
+                if (_logger.isDebugEnabled())
+                {
+                    _logger.debug("Enqueue of message number " + message.getMessageNumber() + " to transaction log. Queue : " + queue.getNameShortString());
+                }
 
-                TransactionLog.Transaction txn = _transactionLog.newTransaction();
+                txn = _transactionLog.newTransaction();
                 txn.enqueueMessage(queue, message.getMessageNumber());
                 txn.commitTran();
+                txn = null;
             }
-            postCommitAction.postCommit();
+            postTransactionAction.postCommit();
+            postTransactionAction = null;
         }
         catch (AMQException e)
         {
-            //TODO
-            e.printStackTrace();
-            postCommitAction.onRollback();
-            throw new RuntimeException(e);
+            _logger.error("Error during message enqueue", e);
+            throw new RuntimeException("Error during message enqueue", e);
         }
+        finally
+        {
+            rollbackIfNecessary(postTransactionAction, txn);
+        }
+
 
     }
 
-    public void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postCommitAction)
+    public void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postTransactionAction)
     {
+        TransactionLog.Transaction txn = null;
         try
         {
 
             if(message.isPersistent())
             {
-                TransactionLog.Transaction txn = _transactionLog.newTransaction();
                 Long id = message.getMessageNumber();
-                for(BaseQueue q : queues)
+                for(BaseQueue queue : queues)
                 {
-                    if(q.isDurable())
+                    if (queue.isDurable())
                     {
-                        txn.enqueueMessage(q, id);
+                        if (_logger.isDebugEnabled())
+                        {
+                            _logger.debug("Enqueue of message number " + message.getMessageNumber() + " to transaction log. Queue : " + queue.getNameShortString());
+                        }
+                        if (txn == null)
+                        {
+                            txn = _transactionLog.newTransaction();
+                        }
+                        
+                        txn.enqueueMessage(queue, id);
                     }
                 }
-                txn.commitTran();
+                
+                if (txn != null)
+                {
+                    txn.commitTran();
+                    txn = null;
 
+                }
             }
-            postCommitAction.postCommit();
+            postTransactionAction.postCommit();
+            postTransactionAction = null;
         }
         catch (AMQException e)
         {
-            //TODO
-            postCommitAction.onRollback();
-            throw new RuntimeException(e);
+            _logger.error("Error during message enqueues", e);
+            throw new RuntimeException("Error during message enqueues", e);
+        }
+        finally
+        {
+            rollbackIfNecessary(postTransactionAction, txn);
         }
 
     }
 
+
     public void commit()
     {
-
     }
 
     public void rollback()
     {
+    }
 
+    private void rollbackIfNecessary(Action postTransactionAction, TransactionLog.Transaction txn)
+    {
+        if (txn != null)
+        {
+            try
+            {
+                txn.abortTran();
+            }
+            catch (AMQStoreException e)
+            {
+                _logger.error("Abort transaction failed", e);
+                // Deliberate decision not to re-throw this exception.  Rationale:  we can only reach here if a previous
+                // TransactionLog method has ended in Exception.  If we were to re-throw here, we would prevent
+                // our caller from receiving the original exception (which is likely to be more revealing of the underlying error).
+            }
+        }
+        if (postTransactionAction != null)
+        {
+            postTransactionAction.onRollback();
+        }
     }
+
 }
diff --git a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/LocalTransaction.java b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/LocalTransaction.java
index 7c9276dbdc..a04c743be1 100755
--- a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/LocalTransaction.java
+++ b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/LocalTransaction.java
@@ -21,21 +21,29 @@ package org.apache.qpid.server.txn;
  */
 
 
-import org.apache.qpid.server.queue.AMQQueue;
-import org.apache.qpid.server.queue.QueueEntry;
-import org.apache.qpid.server.queue.BaseQueue;
+import java.util.ArrayList;
+import java.util.Collection;
+import java.util.List;
+
+import org.apache.log4j.Logger;
+import org.apache.qpid.AMQException;
 import org.apache.qpid.server.message.EnqueableMessage;
 import org.apache.qpid.server.message.ServerMessage;
+import org.apache.qpid.server.queue.BaseQueue;
+import org.apache.qpid.server.queue.QueueEntry;
 import org.apache.qpid.server.store.TransactionLog;
-import org.apache.qpid.AMQException;
-
-import java.util.List;
-import java.util.ArrayList;
-import java.util.Collection;
 
+/**
+ * A concrete implementation of ServerTransaction where enqueue/dequeue
+ * operations share a single long-lived transaction.
+ * 
+ * The caller is responsible for invoking commit() (or rollback()) as necessary.
+ */
 public class LocalTransaction implements ServerTransaction
 {
-    private final List<Action> _postCommitActions = new ArrayList<Action>();
+    protected static final Logger _logger = Logger.getLogger(LocalTransaction.class);
+
+    private final List<Action> _postTransactionActions = new ArrayList<Action>();
 
     private volatile TransactionLog.Transaction _transaction;
     private TransactionLog _transactionLog;
@@ -45,17 +53,23 @@ public class LocalTransaction implements ServerTransaction
         _transactionLog = transactionLog;
     }
 
-    public void addPostCommitAction(Action postCommitAction)
+    public void addPostTransactionAction(Action postTransactionAction)
     {
-        _postCommitActions.add(postCommitAction);
+        _postTransactionActions.add(postTransactionAction);
     }
 
-    public void dequeue(BaseQueue queue, EnqueableMessage message, Action postCommitAction)
+    public void dequeue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction)
     {
+        _postTransactionActions.add(postTransactionAction);
+
         if(message.isPersistent() && queue.isDurable())
         {
             try
             {
+                if (_logger.isDebugEnabled())
+                {
+                    _logger.debug("Dequeue of message number " + message.getMessageNumber() + " from transaction log. Queue : " + queue.getNameShortString());
+                }
 
                 beginTranIfNecessary();
                 _transaction.dequeueMessage(queue, message.getMessageNumber());
@@ -63,23 +77,31 @@ public class LocalTransaction implements ServerTransaction
             }
             catch(AMQException e)
             {
+                _logger.error("Error during message dequeues", e);
                 tidyUpOnError(e);
             }
         }
-        _postCommitActions.add(postCommitAction);
     }
 
-    public void dequeue(Collection<QueueEntry> queueEntries, Action postCommitAction)
+    public void dequeue(Collection<QueueEntry> queueEntries, Action postTransactionAction)
     {
+        _postTransactionActions.add(postTransactionAction);
+
         try
         {
 
             for(QueueEntry entry : queueEntries)
             {
                 ServerMessage message = entry.getMessage();
-                AMQQueue queue = entry.getQueue();
+                BaseQueue queue = entry.getQueue();
+
                 if(message.isPersistent() && queue.isDurable())
                 {
+                    if (_logger.isDebugEnabled())
+                    {
+                        _logger.debug("Dequeue of message number " + message.getMessageNumber() + " from transaction log. Queue : " + queue.getNameShortString());
+                    }
+
                     beginTranIfNecessary();
                     _transaction.dequeueMessage(queue, message.getMessageNumber());
                 }
@@ -88,9 +110,9 @@ public class LocalTransaction implements ServerTransaction
         }
         catch(AMQException e)
         {
+            _logger.error("Error during message dequeues", e);
             tidyUpOnError(e);
         }
-        _postCommitActions.add(postCommitAction);
 
     }
 
@@ -98,7 +120,7 @@ public class LocalTransaction implements ServerTransaction
     {
         try
         {
-            for(Action action : _postCommitActions)
+            for(Action action : _postTransactionActions)
             {
                 action.onRollback();
             }
@@ -107,14 +129,20 @@ public class LocalTransaction implements ServerTransaction
         {
             try
             {
-                _transaction.abortTran();
+                if (_transaction != null)
+                {
+                    _transaction.abortTran();
+                }
             }
-            catch (Exception e1)
+            catch (Exception abortException)
             {
-                // TODO could try to chain the information to the original error
+                _logger.error("Abort transaction failed while trying to handle previous error", abortException);
+            }
+            finally
+            {
+                _transaction = null;
+                _postTransactionActions.clear();
             }
-            _transaction = null;
-            _postCommitActions.clear();
         }
 
         throw new RuntimeException(e);
@@ -122,6 +150,7 @@ public class LocalTransaction implements ServerTransaction
 
     private void beginTranIfNecessary()
     {
+
         if(_transaction == null)
         {
             try
@@ -135,52 +164,50 @@ public class LocalTransaction implements ServerTransaction
         }
     }
 
-    public void enqueue(BaseQueue queue, EnqueableMessage message, Action postCommitAction)
+    public void enqueue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction)
     {
+        _postTransactionActions.add(postTransactionAction);
+
         if(message.isPersistent() && queue.isDurable())
         {
-            beginTranIfNecessary();
             try
             {
+                if (_logger.isDebugEnabled())
+                {
+                    _logger.debug("Enqueue of message number " + message.getMessageNumber() + " to transaction log. Queue : " + queue.getNameShortString());
+                }
+                
+                beginTranIfNecessary();
                 _transaction.enqueueMessage(queue, message.getMessageNumber());
             }
             catch (Exception e)
             {
+                _logger.error("Error during message enqueue", e);
+
                 tidyUpOnError(e);
             }
         }
-        _postCommitActions.add(postCommitAction);
-
-
     }
 
-    public void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postCommitAction)
+    public void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postTransactionAction)
     {
-
+        _postTransactionActions.add(postTransactionAction);
 
         if(message.isPersistent())
         {
-            if(_transaction == null)
-            {
-                for(BaseQueue queue : queues)
-                {
-                    if(queue.isDurable())
-                    {
-                        beginTranIfNecessary();
-                        break;
-                    }
-                }
-
-
-            }
-
-
             try
             {
                 for(BaseQueue queue : queues)
                 {
                     if(queue.isDurable())
                     {
+                        if (_logger.isDebugEnabled())
+                        {
+                            _logger.debug("Enqueue of message number " + message.getMessageNumber() + " to transaction log. Queue : " + queue.getNameShortString() );
+                        }
+                        
+                        
+                        beginTranIfNecessary();
                         _transaction.enqueueMessage(queue, message.getMessageNumber());
                     }
                 }
@@ -188,12 +215,11 @@ public class LocalTransaction implements ServerTransaction
             }
             catch (Exception e)
             {
+                _logger.error("Error during message enqueue", e);
+
                 tidyUpOnError(e);
             }
         }
-        _postCommitActions.add(postCommitAction);
-
-
     }
 
     public void commit()
@@ -202,55 +228,52 @@ public class LocalTransaction implements ServerTransaction
         {
             if(_transaction != null)
             {
-
                 _transaction.commitTran();
             }
 
-            for(Action action : _postCommitActions)
+            for(Action action : _postTransactionActions)
             {
                 action.postCommit();
             }
         }
         catch (Exception e)
         {
-            for(Action action : _postCommitActions)
+            _logger.error("Failed to commit transaction", e);
+
+            for(Action action : _postTransactionActions)
             {
                 action.onRollback();
             }
-            //TODO
-            throw new RuntimeException(e);
+            throw new RuntimeException("Failed to commit transaction", e);
         }
         finally
         {
             _transaction = null;
-            _postCommitActions.clear();
+            _postTransactionActions.clear();
         }
 
     }
 
     public void rollback()
     {
-
         try
         {
 
             if(_transaction != null)
             {
-
                 _transaction.abortTran();
             }
         }
         catch (AMQException e)
         {
-            //TODO
-            e.printStackTrace();
-            throw new RuntimeException(e);
+            _logger.error("Failed to rollback transaction", e);
+            throw new RuntimeException("Failed to rollback transaction", e);
         }
         finally
         {
             try
             {
-                for(Action action : _postCommitActions)
+                for(Action action : _postTransactionActions)
                 {
                     action.onRollback();
                 }
@@ -258,7 +281,7 @@ public class LocalTransaction implements ServerTransaction
             finally
             {
                 _transaction = null;
-                _postCommitActions.clear();
+                _postTransactionActions.clear();
             }
         }
     }
diff --git a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/ServerTransaction.java b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/ServerTransaction.java
index f3ef6569f3..b61b8a5c64 100755
--- a/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/ServerTransaction.java
+++ b/qpid/java/broker/src/main/java/org/apache/qpid/server/txn/ServerTransaction.java
@@ -27,14 +27,24 @@ import org.apache.qpid.server.queue.QueueEntry;
 import java.util.Collection;
 import java.util.List;
 
+
+/**
+ * The ServerTransaction interface allows a set enqueue/dequeue operations to be
+ * performed against the transaction belonging the underlying TransactionLog object.
+ * 
+ * Typically all ServerTransaction implementations decide if a message should be enlisted
+ * into a store transaction by examining the durable property of the queue, and the persistence
+ * property of the message. 
+ * 
+ * A caller may register a list of post transaction Actions to be
+ * performed on commit() (or rollback()).
+ * 
+ */
 public interface ServerTransaction
 {
-
-    void addPostCommitAction(Action postCommitAction);
-
-
-
-
+    /** 
+     * Represents an action to be performed on transaction commit or rollback
+     */
     public static interface Action
     {
         public void postCommit();
@@ -42,16 +52,52 @@ public interface ServerTransaction
         public void onRollback();
     }
 
-    void dequeue(BaseQueue queue, EnqueableMessage message, Action postCommitAction);
-
-    void dequeue(Collection<QueueEntry> ackedMessages, Action postCommitAction);
-
-    void enqueue(BaseQueue queue, EnqueableMessage message, Action postCommitAction);
-
-    void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postCommitAction);
-
-
+    /** 
+     * Register an Action for execution after transaction commit or rollback.  Actions
+     * will be executed in the order in which they are registered.
+     */
+    void addPostTransactionAction(Action postTransactionAction);
+
+    /** 
+     * Dequeue a message from a queue registering a post transaction action.
+     * 
+     * A store operation will result only for a persistent message on a durable queue.
+     */
+    void dequeue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction);
+
+    /** 
+     * Dequeue a message(s) from queue(s) registering a post transaction action.
+     * 
+     * Store operations will result only for a persistent messages on durable queues.
+     */
+    void dequeue(Collection<QueueEntry> messages, Action postTransactionAction);
+
+    /** 
+     * Enqueue a message to a queue registering a post transaction action.
+     * 
+     * A store operation will result only for a persistent message on a durable queue.
+     */
+    void enqueue(BaseQueue queue, EnqueableMessage message, Action postTransactionAction);
+
+    /** 
+     * Enqueue a message(s) to queue(s) registering a post transaction action.
+     * 
+     * Store operations will result only for a persistent messages on durable queues.
+     */
+    void enqueue(List<? extends BaseQueue> queues, EnqueableMessage message, Action postTransactionAction);
+
+    /** 
+     * Commit the transaction represented by this object.
+     * 
+     * If the caller has registered one or more Actions, the postCommit() method on each will
+     * be executed immediately after the underlying transaction has committed. 
+     */
     void commit();
 
+    /** Rollback the transaction represented by this object.
+     * 
+     * If the caller has registered one or more Actions, the onRollback() method on each will
+     * be executed immediately after the underlying transaction has rolled-back. 
+     */
     void rollback();
 }