8 Replies Latest reply on Jan 9, 2007 9:53 AM by manik

    Problem with transaction timeout [critical]

    jacek187

      Hi

      I'm using latest TreeCache 1.4.0SP1 with WebLogic 9.1.
      There is a problem with transaction timeout. On WebLogic, when transaction timeouts server is dooing transacion synchronization in separate thread....
      It causes problems with following scenario:

      1. Thread A is invoking transactional method foo() (in SLSB etc). New transaction starts with timeout 30 sec.
      2. Method foo() is making call into DB, putting/getting data from/into TreeCache and making businness operations. This is long runing method (60sec)
      3. On end foo() method server is trying commit transaction, but this transaction is timed out, so now server start separate thread Y. Thread Y is making call into OrderedSynchronizationHandler.afterCompletion() synchronization handler. Main thred X is calling main code.

      And this is problem, because in main looks like:

       try{
       FooManager.foo();
       }catch(RuntimeException e){
       logger.error("Exception catched:",e);
       }
       TreeCacheUtils.putIntoCache("KEY", "VALUE");
      

      any exception from foo() method is catched and logged, and any next eny variable is putted into cache (and view with error message is rendered etc)

      But there is a hazrd risk, because sometimes main code is making operation on TreeCache BEFORE thread Y is calling afterCompletion method!!!!!!

      this causes unexpected effect, because TreeCache has still information about GloblTransaction (information about transactions is yet not updated in TXInterceptor). TreeCache is trying lock node with information about caller GlobalTransaction, but this transaction dosen't exist for weblogic TransactionManager!
      And now when we looks in TreeCache logs we can see, that write lock is aquired and NEVER RELEASED!!!!!!!


      2007-01-04 10:14:37,310 DEBUG - Attempting to lock node /NODE_KEY for owner GlobalTransaction:<192.168.141.1:2100>:1
      2007-01-04 10:14:37,310 DEBUG - acquiring WL: fqn=/NODE_KEY, caller=GlobalTransaction:<192.168.141.1:2100>:1, lock=read owners=[GlobalTransaction:<192.168.141.1:2100>:1]
      2007-01-04 10:14:37,310 DEBUG - upgrading RL to WL for GlobalTransaction:<192.168.141.1:2100>:1, timeout=10000, locks: Read lock owners: [GlobalTransaction:<192.168.141.1:2100>:1]
      Write lock owner: null

      2007-01-04 10:14:37,310 DEBUG - upgrading lock for /NODE_KEY
      2007-01-04 10:14:37,310 DEBUG - acquired WL: fqn=/NODE_KEY, caller=GlobalTransaction:<192.168.141.1:2100>:1, lock=write owner=GlobalTransaction:<192.168.141.1:2100>:1
      2007-01-04 10:14:37,310 ERROR - transaction entry not found for (gtx=GlobalTransaction:<192.168.141.1:2100>:1)
      2007-01-04 10:14:37,310 DEBUG - Invoking method _put(null, /NODE_KEY, NODE_VALUE, Thu Jan 04 10:14:37 CET 2007, true) on cache.
      2007-01-04 10:14:37,310 DEBUG - _put(null, "/NODE_KEY", NODE_VALUE, Thu Jan 04 10:14:37 CET 2007)
      2007-01-04 10:14:37,310 DEBUG - Attempting to release locks on current thread. Lock table is {}

      This is critical bug for me, because from now any operation on NODE_KEY causes org.jboss.cache.lock.TimeoutException: failure acquiring lock exception!
      And i must restart server!!!!

      Jacek

        • 1. Re: Problem with transaction timeout [critical]
          jacek187

          Hi

          Because this bug is very important for me, I looked into source code and I think, that main problem is:

          GlobalTransaction table is stored in ThreadLocal in TreeCache object, so if Weblogic calls transaction synchronization in another thread, new InvocationContext for this thread is created (new and empty) and this new created invocationContext is cleared in method TxInterceptor.scrubInvocationCtx().
          Of course invocationContext from main thread is NOT cleared and information about non-exist GlobalTransaction still is used while reda/write opration on nodes.

          Question: How synchronize calls between separate threads ? Should be transaction identifier used?

          Jacek

          • 2. Re: Problem with transaction timeout [critical]
            jacek187

            Simplest as possible working example for this issue:

            package test;
            
            import javax.naming.InitialContext;
            import javax.transaction.Synchronization;
            import javax.transaction.Transaction;
            import javax.transaction.TransactionManager;
            
            public class RollbackTest {
             public static void test(){
             try{
             InitialContext ic = new InitialContext();
             TransactionManager tm = (TransactionManager)ic.lookup( "javax.transaction.TransactionManager" );
             try {
             tm.setTransactionTimeout(1);//set 1 sec transaction timeout
             tm.begin();//start transaction
             Transaction t = tm.getTransaction();
             t.registerSynchronization(new Synchronization() {//add new synchronization handler
            
             public void afterCompletion(int arg0) {
             System.out.println("After:"+Thread.currentThread().hashCode());
             }
            
             public void beforeCompletion() {
             System.out.println("Before:"+Thread.currentThread().hashCode());
             }
             });
             Thread.sleep(20000);//wait 20 secs
             System.out.println("Transaction before commit:"+Thread.currentThread().hashCode());
             tm.commit();//try commit tranwsaction, TransactionTimedOut exception should be throwed
             System.out.println("Transaction after commit:"+Thread.currentThread().hashCode());
             } catch (Exception e) {
             System.out.println("Fake method error: " + e.getMessage());
             }
             }catch(Exception e){
             e.printStackTrace();
             }
             }
            }
            


            Run this code from any non-transactional context, for example from jsp page.
            <jsp:directive.page import="test.RollbackTest"/>Hello!!
            <%
             RollbackTest.test();
            %>
            


            Output is:
            After:-1257420086
            Transaction before commit:668113225
            Fake method error: Transaction timed out after 0 seconds
            BEA1-00058EF7774602E8BAA1

            Note:
            when you set sleep() value less than 10 secs, weblogic dosen't create separate thread for rollback!

            • 3. Re: Problem with transaction timeout [critical]
              manik

              This is an interesting issue, that a separate thread is used for commits and rollbacks.

              I need to investigate how quickly (or otherwise) such a fix can be implemented, to make it into 1.4.1.GA (failing that, an SP). Do you have a unit test that recreates this outside of WebLogic, i.e., as a standalone JUnit test?

              • 4. Re: Problem with transaction timeout [critical]
                manik

                I've put together a test, see if this accurately describes your problem. It is in CVS, in Branch_JBossCache_1_4_0.

                Or, view the test online.

                • 5. Re: Problem with transaction timeout [critical]
                  jacek187

                  Your test is not correct - If rollback() or commit() from DummyTransactionManager is invoked in separate thread, DummyBaseTransactionManager can't find transaction stored in thread_local and IllegalStateException("thread not associated with transaction"); is throwed instead real rollback operation execution.

                  This is unit test that recreates this problem outside WebLogic. AsyncRollbackTransactionManager works like weblogic transaction manager.
                  Note: only rollbacks (and not all !!!!! Only timed out transactions and only if transaction was checked by internal transactionManager timer!) are executed in separate thread!


                  AsyncRollbackTxTest

                  package org.jboss.cache.transaction;
                  
                  import javax.transaction.SystemException;
                  import javax.transaction.TransactionManager;
                  
                  import junit.framework.TestCase;
                  
                  import org.jboss.cache.CacheException;
                  import org.jboss.cache.Fqn;
                  import org.jboss.cache.TreeCache;
                  
                  /**
                   * Test behaviour of async rollback timeouted transaction
                   *
                   * @author <a href="mailto:jhalat@infovide.pl">Jacek Halat</a>
                   * @since 1.4.0
                   */
                  public class AsyncRollbackTxTest extends TestCase
                  {
                   private TreeCache cache;
                   private TransactionManager tm;
                   private Fqn fqn = Fqn.fromString("/test");
                  
                   protected void setUp() throws Exception
                   {
                   cache = new TreeCache();
                   cache.setTransactionManagerLookupClass("org.jboss.cache.transaction.AsyncRollbackTransactionManagerLookup");
                   cache.startService();
                   tm = cache.getTransactionManager();
                   }
                  
                   protected void tearDown()
                   {
                   try
                   {
                   if (tm != null && tm.getTransaction() != null)
                   {
                   try
                   {
                   tm.rollback();
                   }
                   catch (SystemException e)
                   {
                   // do nothing
                   }
                   }
                   }
                   catch (SystemException e)
                   {
                   // do nothing
                   }
                   if (cache != null) cache.stopService();
                   cache = null;
                   tm = null;
                   }
                  
                   public void testControl() throws Exception
                   {
                   assertEquals(0, cache.getNumberOfLocksHeld());
                   tm.begin();
                   cache.put(fqn, "k", "v");
                   assertEquals(1, cache.getNumberOfLocksHeld());
                   tm.rollback();
                   assertEquals(0, cache.getNumberOfLocksHeld());
                   }
                  
                   public void testRollbackInDifferentThread() throws Exception
                   {
                   tm.setTransactionTimeout(2);
                   tm.begin();
                   cache.put(fqn, "k", "v");
                   assertEquals(1, cache.getNumberOfLocksHeld());
                   Thread.sleep(5000);
                   try{
                   tm.commit();
                   }catch(Exception e){
                   e.printStackTrace();
                   }
                   assertEquals(0, cache.getNumberOfLocksHeld());
                   cache.put(fqn, "k", "v");//Executed in Not transactional context
                  // assertEquals(0, cache.getNumberOfLocksHeld());
                   SeparateThread t = new SeparateThread();
                   t.start();
                   t.join();
                   if (t.getException()!=null){
                   throw t.getException();
                   }
                   }
                   private class SeparateThread extends Thread{
                   Exception e = null;
                   public Exception getException() {
                   return e;
                   }
                   @Override
                   public void run() {
                   try {
                   cache.put(fqn, "k", "v");
                   assertEquals(0, cache.getNumberOfLocksHeld());
                   } catch (CacheException e) {
                   this.e = e;
                   }
                   }
                   };
                  }
                  
                  


                  AsyncRollbackTransactionManager
                  package org.jboss.cache.transaction;
                  
                  import java.util.HashMap;
                  import java.util.Iterator;
                  import java.util.Map;
                  import java.util.Properties;
                  
                  import javax.naming.Context;
                  import javax.naming.InitialContext;
                  import javax.naming.NamingException;
                  import javax.transaction.HeuristicMixedException;
                  import javax.transaction.HeuristicRollbackException;
                  import javax.transaction.InvalidTransactionException;
                  import javax.transaction.NotSupportedException;
                  import javax.transaction.RollbackException;
                  import javax.transaction.SystemException;
                  import javax.transaction.Transaction;
                  
                  public class AsyncRollbackTransactionManager extends DummyTransactionManager{
                   static AsyncRollbackTransactionManager instance=null;
                  
                   public static DummyTransactionManager getInstance() {
                   if(instance == null) {
                   instance=new AsyncRollbackTransactionManager();
                   try {
                   Properties p=new Properties();
                   p.put(Context.INITIAL_CONTEXT_FACTORY, "org.jboss.cache.transaction.DummyContextFactory");
                   Context ctx=new InitialContext(p);
                   ctx.bind("java:/TransactionManager", instance);
                   ctx.bind("UserTransaction", new DummyUserTransaction(instance));
                   }
                   catch(NamingException e) {
                   log.error("binding of DummyTransactionManager failed", e);
                   }
                   }
                   return instance;
                   }
                  
                   private Thread timedOutTransactionsChecker = null;
                   private int timeout = 30;
                   private Map txMap = new HashMap();
                   @Override
                   public void setTransactionTimeout(int seconds) throws SystemException {
                   this.timeout = seconds;
                   }
                   public AsyncRollbackTransactionManager(){
                   timedOutTransactionsChecker = new TimedOutTransactionsChecker();
                   timedOutTransactionsChecker.start();
                   }
                   private class TimedOutTransactionsChecker extends Thread{
                   private boolean running;
                   public TimedOutTransactionsChecker(){
                   }
                   public void run() {
                   running = true;
                   while (running){
                   try {
                   Thread.sleep(500);
                   synchronized(this)
                   {
                   Iterator iterator = txMap.values().iterator();
                   do
                   {
                   if(!iterator.hasNext())
                   break;
                   AsyncRollbackTransaction t = (AsyncRollbackTransaction)iterator.next();
                   try {
                   t.wakeUp();
                   } catch (SystemException e) {
                   e.printStackTrace();
                   }
                  
                   } while(true);
                   }
                   } catch (InterruptedException e) {
                   }
                   }
                   }
                  
                   }
                   @SuppressWarnings("unchecked")
                   @Override
                   public void begin() throws NotSupportedException, SystemException {
                   Transaction currentTx;
                   if((currentTx=getTransaction()) != null)
                   throw new NotSupportedException(Thread.currentThread() +
                   " is already associated with a transaction (" + currentTx + ")");
                   AsyncRollbackTransaction tx=new AsyncRollbackTransaction(this,timeout);
                   setTransaction(tx);
                   txMap.put(tx.generateTransactionId(), tx);
                   }
                   @Override
                   public void rollback() throws IllegalStateException, SecurityException, SystemException {
                   removeTxFromMap();
                   super.rollback();
                   }
                   public void removeTxFromMap() throws SystemException {
                   AsyncRollbackTransaction tx=(AsyncRollbackTransaction) getTransaction();
                   if (tx!=null){
                   txMap.remove(tx.getTransactionId());
                   }
                   }
                   @Override
                   public void commit() throws RollbackException, HeuristicMixedException, HeuristicRollbackException, SecurityException, IllegalStateException, SystemException {
                   AsyncRollbackTransaction tx=(AsyncRollbackTransaction) getTransaction();
                   if (tx!=null){
                   txMap.remove(tx.getTransactionId());
                   }
                   super.commit();
                   }
                   @Override
                   public void resume(Transaction tx) throws InvalidTransactionException, IllegalStateException, SystemException {
                   //TODO Not implemented TX timeout counting
                   super.resume(tx);
                   }
                   @Override
                   public Transaction suspend() throws SystemException {
                   //TODO Not implemented TX timeout counting
                   return super.suspend();
                   }
                  }
                  
                  
                  


                  AsyncRollbackTransactionManagerLookup
                  package org.jboss.cache.transaction;
                  
                  import javax.transaction.TransactionManager;
                  
                  import org.jboss.cache.TransactionManagerLookup;
                  
                  public class AsyncRollbackTransactionManagerLookup implements TransactionManagerLookup{
                   public TransactionManager getTransactionManager() throws Exception {
                   return AsyncRollbackTransactionManager.getInstance();
                   }
                  
                  }
                  



                  AsyncRollbackTransaction
                  package org.jboss.cache.transaction;
                  
                  import javax.transaction.SystemException;
                  
                  
                  public class AsyncRollbackTransaction extends DummyTransaction {
                   private static long transactionNums = 0;
                  
                   private long transactionId;
                  
                   private long beginTimeMillis;
                  
                   private int timeoutSec;
                  
                   public AsyncRollbackTransaction(DummyBaseTransactionManager tm, int timeout) {
                   super(tm);
                   this.timeoutSec = timeout;
                   this.beginTimeMillis = System.currentTimeMillis();
                   }
                  
                   /**
                   * @return the transactionId
                   */
                   public long getTransactionId() {
                   return transactionId;
                   }
                  
                   public long generateTransactionId() {
                   long result = 0;
                   synchronized (AsyncRollbackTransaction.class) {
                   transactionNums++;
                   result = transactionNums;
                   }
                   this.transactionId = result;
                   return result;
                   }
                  
                   final int getTimeoutSeconds() {
                   return timeoutSec;
                   }
                  
                   protected final void asyncRollback() throws SystemException {
                   Thread asyncRollbackThread = new Thread() {
                   public void run() {
                   try {
                   rollback();
                   } catch (Exception exception) {
                   }
                   }
                   };
                   ((AsyncRollbackTransactionManager)tm_).removeTxFromMap();
                   asyncRollbackThread.start();
                   }
                  
                   public void wakeUp() throws SystemException {
                   if (isTransactionTimedOut()) {
                   asyncRollback();
                   }
                   }
                   private boolean isTransactionTimedOut() {
                   return (System.currentTimeMillis() - beginTimeMillis) > (timeoutSec * 1000);
                   }
                  }
                  


                  • 6. Re: Problem with transaction timeout [critical]
                    jacek187

                    Small cosmetic test fix:

                    AsyncRollbackTransactionManager

                    package org.jboss.cache.transaction;
                    
                    import java.util.HashMap;
                    import java.util.Iterator;
                    import java.util.Map;
                    import java.util.Properties;
                    
                    import javax.naming.Context;
                    import javax.naming.InitialContext;
                    import javax.naming.NamingException;
                    import javax.transaction.HeuristicMixedException;
                    import javax.transaction.HeuristicRollbackException;
                    import javax.transaction.InvalidTransactionException;
                    import javax.transaction.NotSupportedException;
                    import javax.transaction.RollbackException;
                    import javax.transaction.SystemException;
                    import javax.transaction.Transaction;
                    
                    public class AsyncRollbackTransactionManager extends DummyTransactionManager{
                     static AsyncRollbackTransactionManager instance=null;
                    
                     public static DummyTransactionManager getInstance() {
                     if(instance == null) {
                     instance=new AsyncRollbackTransactionManager();
                     try {
                     Properties p=new Properties();
                     p.put(Context.INITIAL_CONTEXT_FACTORY, "org.jboss.cache.transaction.DummyContextFactory");
                     Context ctx=new InitialContext(p);
                     ctx.bind("java:/TransactionManager", instance);
                     ctx.bind("UserTransaction", new DummyUserTransaction(instance));
                     }
                     catch(NamingException e) {
                     log.error("binding of DummyTransactionManager failed", e);
                     }
                     }
                     return instance;
                     }
                    
                     private Thread timedOutTransactionsChecker = null;
                     private int timeout = 30;
                     private Map txMap = new HashMap();
                     @Override
                     public void setTransactionTimeout(int seconds) throws SystemException {
                     this.timeout = seconds;
                     }
                     public AsyncRollbackTransactionManager(){
                     timedOutTransactionsChecker = new TimedOutTransactionsChecker();
                     timedOutTransactionsChecker.start();
                     }
                     private class TimedOutTransactionsChecker extends Thread{
                     private boolean running;
                     public TimedOutTransactionsChecker(){
                     }
                     public void run() {
                     running = true;
                     while (running){
                     try {
                     Thread.sleep(500);
                     synchronized(this)
                     {
                     Iterator iterator = txMap.values().iterator();
                     do
                     {
                     if(!iterator.hasNext())
                     break;
                     AsyncRollbackTransaction t = (AsyncRollbackTransaction)iterator.next();
                     try {
                     t.wakeUp();
                     } catch (SystemException e) {
                     e.printStackTrace();
                     }
                    
                     } while(true);
                     }
                     } catch (InterruptedException e) {
                     }
                     }
                     }
                    
                     }
                     @SuppressWarnings("unchecked")
                     @Override
                     public void begin() throws NotSupportedException, SystemException {
                     Transaction currentTx;
                     if((currentTx=getTransaction()) != null)
                     throw new NotSupportedException(Thread.currentThread() +
                     " is already associated with a transaction (" + currentTx + ")");
                     AsyncRollbackTransaction tx=new AsyncRollbackTransaction(this,timeout);
                     setTransaction(tx);
                     txMap.put(tx.generateTransactionId(), tx);
                     }
                     @Override
                     public void rollback() throws IllegalStateException, SecurityException, SystemException {
                     removeTxFromMap((AsyncRollbackTransaction) getTransaction());
                     super.rollback();
                     }
                     public void removeTxFromMap(AsyncRollbackTransaction tx) throws SystemException {
                     if (tx!=null){
                     txMap.remove(tx.getTransactionId());
                     }
                     }
                     @Override
                     public void commit() throws RollbackException, HeuristicMixedException, HeuristicRollbackException, SecurityException, IllegalStateException, SystemException {
                     AsyncRollbackTransaction tx=(AsyncRollbackTransaction) getTransaction();
                     if (tx!=null){
                     txMap.remove(tx.getTransactionId());
                     }
                     super.commit();
                     }
                     @Override
                     public void resume(Transaction tx) throws InvalidTransactionException, IllegalStateException, SystemException {
                     //TODO Not implemented TX timeout counting
                     super.resume(tx);
                     }
                     @Override
                     public Transaction suspend() throws SystemException {
                     //TODO Not implemented TX timeout counting
                     return super.suspend();
                     }
                    }
                    


                    AsyncRollbackTransaction
                    package org.jboss.cache.transaction;
                    
                    import javax.transaction.SystemException;
                    
                    
                    public class AsyncRollbackTransaction extends DummyTransaction {
                     private static long transactionNums = 0;
                    
                     private long transactionId;
                    
                     private long beginTimeMillis;
                    
                     private int timeoutSec;
                    
                     public AsyncRollbackTransaction(DummyBaseTransactionManager tm, int timeout) {
                     super(tm);
                     this.timeoutSec = timeout;
                     this.beginTimeMillis = System.currentTimeMillis();
                     }
                    
                     /**
                     * @return the transactionId
                     */
                     public long getTransactionId() {
                     return transactionId;
                     }
                    
                     public long generateTransactionId() {
                     long result = 0;
                     synchronized (AsyncRollbackTransaction.class) {
                     transactionNums++;
                     result = transactionNums;
                     }
                     this.transactionId = result;
                     return result;
                     }
                    
                     final int getTimeoutSeconds() {
                     return timeoutSec;
                     }
                    
                     protected final void asyncRollback() throws SystemException {
                     Thread asyncRollbackThread = new Thread() {
                     public void run() {
                     try {
                     rollback();
                     } catch (Exception exception) {
                     }
                     }
                     };
                     ((AsyncRollbackTransactionManager)tm_).removeTxFromMap(this);
                     asyncRollbackThread.start();
                     }
                    
                     public void wakeUp() throws SystemException {
                     if (isTransactionTimedOut()) {
                     asyncRollback();
                     }
                     }
                     private boolean isTransactionTimedOut() {
                     return (System.currentTimeMillis() - beginTimeMillis) > (timeoutSec * 1000);
                     }
                    }
                    


                    • 7. Re: Problem with transaction timeout [critical]
                      brian.stansberry

                      Thanks for these. Could you attach to the JIRA you opened rather than pasting in the forum?

                      • 8. Re: Problem with transaction timeout [critical]
                        manik

                        After exchanging some emails with Jacek and fine-tuning the test to accuratelly recreate the problem, I've found and fixed this. The fix is in 1.4.1.GA and 2.0.0.ALPHA2, details of the solution are documented on JBCACHE-923.

                        Updated unit tests are in CVS.

                        Thanks for your help, Jacek!

                        - Manik