1 Reply Latest reply on Sep 1, 2004 12:51 PM by Bela Ban

    Problem with tx in TreeCacheMBean

    aguenther Newbie

      Hi There,

      I used the TreeCache as MBean in Jboss 3.2.4 with JbossCache (cvs head).
      There seems to be a problem using UserTransactions in this config.
      The cache is configured with the following params:

      <attribute name="TransactionManagerLookupClass">org.jboss.cache.JBossTransactionManagerLookup</attribute>
       <attribute name="IsolationLevel">SERIALIZABLE</attribute>
       <attribute name="CacheMode">REPL_SYNC</attribute>
      


      I have modified the Bank-Example and pack it into a Stateless EJB using
      few "invokes" to call the TreeCacheMBean ("put" and "get" only). A little
      junit-test like ConcurrentUnitTestCase.java to test it (calls the "txTest"-
      Method in the bean via RMI).

      And that's the problem:
      It seems the SERIALIZABLE - Option in the Cache- Config does not work.
      I extend the Debug- log from Jboss- Cache with the Thread.getCurrentThread() -
      Method and found that more then one threads took access on one Node
      at one Time. There seems to be no isolation between the different transactions.

      I could not found problems in my code. Is there a bug in JBossCache?

      The used EJB as follow:

      package samples;
      
      import javax.ejb.CreateException;
      import javax.management.ObjectName;
      import javax.management.MBeanServer;
      import javax.transaction.UserTransaction;
      
      import org.jboss.cache.lock.LockingException;
      import org.jboss.cache.lock.TimeoutException;
      import org.jboss.mx.util.MBeanServerLocator;
      
      import org.apache.log4j.*;
      
      /**
       * @ejb.bean
       * type="Stateless"
       * name="JBossCacheTest"
       * jndi-name="ejb/JBossCacheTest"
       * local-jndi-name="ejb/local/JBossCacheTest"
       * view-type="both"
       * transaction-type="Bean"
       *
       * @ejb.interface generate="local,remote"
       * extends="javax.ejb.EJBObject"
       * local-extends="javax.ejb.EJBLocalObject"
       * remote-pattern="JBossCacheTest"
       * local-pattern="JBossCacheTestLocal"
       *
       * @ejb.home generate="true"
       * extends="javax.ejb.EJBHome"
       * local-extends="javax.ejb.EJBLocalHome"
       * remote-pattern="JBossCacheTestHome"
       * local-pattern="JBossCacheTestLocalHome"
       *
       * @ejb.transaction type="Supports"
       *
       * @jboss.container-configuration name="Standard Stateless SessionBean"
       */
      public class JBossCacheTestEJB implements javax.ejb.SessionBean, javax.transaction.Status
      {
       MBeanServer server = null;
       ObjectName cacheService = null;
       static final String OBJECT_NAME = "jboss.cache:service=TreeCache";
       private static Logger logger_ = Logger.getLogger(JBossCacheTestEJB.class);
      
       final String NODE = "/cachetest";
       final int ROLLBACK_CHANCE = 100;
      
       static String customer[] = {"cu1", "cu2", "cu3"};
      
       public javax.ejb.SessionContext sctx;
      
       public void ejbCreate()
       {
       }
      
       public void ejbActivate () throws javax.ejb.EJBException, java.rmi.RemoteException
       {
       }
      
       public void ejbPassivate () throws javax.ejb.EJBException, java.rmi.RemoteException
       {
       }
      
       public void ejbRemove () throws javax.ejb.EJBException, java.rmi.RemoteException
       {
       }
      
       public void setSessionContext (javax.ejb.SessionContext sessionContext) throws javax.ejb.EJBException, java.rmi.RemoteException
       {
       try
       {
       sctx = sessionContext;
       }
       catch(Exception e)
       {
       e.printStackTrace();
       }
       }
      
       /**
       * @ejb.interface-method
       */
       public int txTest(int iTestLoops)
       {
       int iErr = 0;
       try
       {
       getTreeCacheMBean();
       UserTransaction tx = sctx.getUserTransaction();
       out("got utx (" + tx + ")");
      
       // initializing tree if iTestLoops == 0 or nodes don't exists
       tx.begin();
       if(this.get(NODE) == null || iTestLoops == 0)
       {
       this.put(NODE, "cu1", new Integer(1000));
       this.put(NODE, "cu2", new Integer(1000));
       this.put(NODE, "cu3", new Integer(1000));
       }
       tx.commit();
      
       runTest(iTestLoops);
       }
       catch(Exception e)
       {
       e.printStackTrace();
       iErr = -2;
       }
       return iErr;
       }
      
       /**
       *
       */
       private void runTest(int iTestLoops)
       {
       int count = 3;
       UserTransaction tx = null;
       try
       {
       boolean again = false;
       int src = 0;
       int dst = 0;
       int amo = 0;
       int cnt =0;
       while(cnt < iTestLoops)
       {
       tx = sctx.getUserTransaction();
      // out("got utx (" + tx + ")");
      
       if(!again)
       {
       src = (int) (Math.random()*count);
       dst = (int) (Math.random()*(count-1));
       amo =1+ (int) (Math.random()*20);
       if(dst>=src) dst++;
       }
      
       try
       {
       tx.begin();
       int sum = deposit(customer[src], customer[dst], amo, tx);
      
       if(tx.getStatus() == STATUS_ACTIVE)
       {
       if(sum != 3000) throw new Exception("sum failure (sum = " + sum + ", cnt = " + cnt + ")");
       tx.commit();
       }
       else /* if(tx.getStatus() == STATUS_MARKED_ROLLBACK) */
       tx.rollback();
       again = false;
       }
       catch(Throwable e)
       {
       tx.rollback();
       e.printStackTrace();
       again = true;
       }
       cnt++;
       }
       }
       catch (Throwable t)
       {
       t.printStackTrace();
       }
       }
      
       /**
       * Posting
       */
       public int deposit(String from, String to, int amount, UserTransaction tx) throws Exception
       {
       out("deposit("+from+", "+to+", "+amount+") called.");
       try
       {
       int act1, act2;
      
       act1 = ((Integer) this.get(NODE, from)).intValue();
       act2 = ((Integer) this.get(NODE, to)).intValue();
      
       // eventually rollback the transaction
       if((int)(Math.random() * ROLLBACK_CHANCE) == 0)
       {
       out("!!!manually set rollback ("+from+", "+to+", "+amount+").");
       tx.setRollbackOnly();
       throw new Exception("Manually set rollback!");
       }
      
       this.put(NODE, from, new Integer(act1-amount)); // debit
       this.put(NODE, to, new Integer(act2+amount)); // credit
       }
       catch(Exception e)
       {
       e.printStackTrace();
       out("exception - rollback ("+from+", "+to+", "+amount+")");
       }
       finally
       {
       // close resources aquired safely
       }
      
       int i0 = ((Integer) this.get(NODE, customer[0])).intValue();
       int i1 = ((Integer) this.get(NODE, customer[1])).intValue();
       int i2 = ((Integer) this.get(NODE, customer[2])).intValue();
      
       int sum = i0 + i1 + i2;
       out("deposit("+from+", "+to+", "+amount+") finished. (sum = " + sum + " = " +i0 + " + " + i1 + " + " + i2 + ")");
       return sum;
       }
      
       /**
       * retrieving amounts of accounts
       */
       private void out(String s)
       {
       logger_.info("Thread[" + Thread.currentThread() + "]: " + s);
       }
      
       private void getTreeCacheMBean() throws Exception
       {
       try
       {
       cacheService = new ObjectName(OBJECT_NAME);
       server = MBeanServerLocator.locate();
       }
       catch (Exception ex)
       {
       throw new CreateException(ex.toString());
       }
       }
      
       // wrapper methods for MBean calls
       /**
       * @param fqn
       * @param key
       * @return
       * @throws LockingException
       * @throws TimeoutException
       */
       private Object get(String fqn, String key) throws LockingException, TimeoutException, Exception
       {
       return server.invoke(cacheService, "get",
       new Object[]{fqn, key},
       new String[]{String.class.getName(),
       Object.class.getName()});
       }
      
       /**
       * @param fqn
       * @return
       * @throws LockingException
       * @throws TimeoutException
       */
       private org.jboss.cache.Node get(String fqn) throws LockingException, TimeoutException, Exception
       {
       return (org.jboss.cache.Node) (server.invoke(cacheService, "get",
       new Object[]{fqn},
       new String[]{String.class.getName()}));
       }
      
       /**
       * @param fqn
       * @param key
       * @param value
       * @throws Exception
       */
       private void put(String fqn, String key, Object value) throws Exception
       {
       Object[] args = {fqn, key, value};
       String[] sig = {String.class.getName(),
       Object.class.getName(),
       Object.class.getName()};
      
       server.invoke(cacheService, "put", args, sig);
       }
      }
      


      the code of the tester:

      /*
       *
       * JBoss, the OpenSource J2EE webOS
       *
       * Distributable under LGPL license.
       * See terms of license at gnu.org.
       */
      package samples.test;
      
      import junit.framework.Test;
      import junit.framework.TestCase;
      import junit.framework.TestSuite;
      import org.jboss.cache.TreeCache;
      import org.jboss.cache.lock.IsolationLevel;
      import org.jboss.logging.Logger;
      
      import samples.*;
      
      /**
       * Unit test Remote TreeCache in Application Server
       */
      public class ConcurrentUnitTestCase extends TestCase
      {
       private Logger logger_ = Logger.getLogger(ConcurrentUnitTestCase.class);
      
       public class rmiThread extends Thread
       {
       private JBossCacheTest jbossCacheTest = null;
      
       private void connect(String sServeradressRMI)
       {
       try
       {
       logger_.info("connecting to <" + sServeradressRMI + ">");
      
       java.util.Properties props = new java.util.Properties();
       props.setProperty("java.naming.factory.initial", "org.jnp.interfaces.NamingContextFactory");
       props.setProperty("java.naming.provider.url", sServeradressRMI);
       props.setProperty("java.naming.factory.url.pkgs", "org.jboss.naming");
      
       javax.naming.InitialContext iC = new javax.naming.InitialContext(props);
       Object home = iC.lookup(JBossCacheTestHome.JNDI_NAME);
       JBossCacheTestHome home_ =(JBossCacheTestHome)javax.rmi.PortableRemoteObject.narrow(home, JBossCacheTestHome.class);
       jbossCacheTest = home_.create();
       }
       catch(Exception e)
       {
       e.printStackTrace();
       }
       }
      
       public void run()
       {
       try
       {
       connect(System.getProperty("RMITestServer", "localhost:1099"));
       jbossCacheTest.txTest(2000);
       }
       catch(Exception e)
       {
       e.printStackTrace();
       fail(e.toString());
       }
       }
       }
      
       public ConcurrentUnitTestCase(String name)
       {
       super(name);
       }
      
       public void setUp() throws Exception
       {
       super.setUp();
       }
      
       public void tearDown() throws Exception
       {
       super.tearDown();
       }
      
       public void test_1()
       {
       try
       {
       setUp();
       work_();
       }
       catch(Exception e)
       {
       e.printStackTrace();
       fail(e.toString());
       }
       }
      
       private void work_()
       {
       rmiThread one, two, three;
       try
       {
       one = new rmiThread();
       two = new rmiThread();
       three = new rmiThread();
      
       one.start();
       two.start();
       three.start();
      
       one.join();
       two.join();
       three.join();
       }
       catch (Exception e)
       {
       e.printStackTrace();
       fail(e.toString());
       }
       }
      
       void log(String msg)
       {
       logger_.debug(" [" + Thread.currentThread() + "]: " + msg);
       }
      
       public static Test suite()
       {
       return new TestSuite(ConcurrentUnitTestCase.class);
       }
      
       public static void main(String[] args)
       {
       junit.textui.TestRunner.run(suite());
       }
      }
      


      and the part of the log that shows overlapping transactions as I understand it:

      ...
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu1, 3) called.
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "975, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]getCurrentTransaction(): registered with transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//60, BranchQual=] as Synchronization listener with global transaction: <test-pc:4356>:52
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:50, "/cachetest", cu2, 1044)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:50, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:50, "/cachetest", cu3, 982)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:50, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "974, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1044, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "982, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]]: deposit(cu2, cu3, 7) finished. (sum = 3000 = 974 + 1044 + 982)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] runPreparePhase(): run remote prepare with async mode: false commit: false and coordinator: test-pc:4356
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]afterCompletion() called (status=COMMITTED)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): called to commit cache with gtx <test-pc:4356>:50
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): releasing lock org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): remove local transaction key TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//58, BranchQual=]
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "982, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]]: deposit(cu2, cu1, 10) called.
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1044, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]getCurrentTransaction(): registered with transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//61, BranchQual=] as Synchronization listener with global transaction: <test-pc:4356>:53
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:51, "/cachetest", cu3, 981)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:51, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:51, "/cachetest", cu2, 1045)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:51, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "974, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1045, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "981, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu2, 1) finished. (sum = 3000 = 974 + 1045 + 981)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] runPreparePhase(): run remote prepare with async mode: false commit: false and coordinator: test-pc:4356
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]afterCompletion() called (status=COMMITTED)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]commit(): called to commit cache with gtx <test-pc:4356>:51
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]commit(): releasing lock org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]commit(): remove local transaction key TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//59, BranchQual=]
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "981, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu2, 17) called.
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "974, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]getCurrentTransaction(): registered with transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//62, BranchQual=] as Synchronization listener with global transaction: <test-pc:4356>:54
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:52, "/cachetest", cu3, 978)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:52, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:52, "/cachetest", cu1, 977)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:52, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "977, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1045, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "978, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu1, 3) finished. (sum = 3000 = 977 + 1045 + 978)
      
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] runPreparePhase(): run remote prepare with async mode: false commit: false and coordinator: test-pc:4356
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]afterCompletion() called (status=COMMITTED)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]commit(): called to commit cache with gtx <test-pc:4356>:52
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]commit(): releasing lock org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]commit(): remove local transaction key TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//60, BranchQual=]
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1045, "true")
      2004-05-11 17:54:01,409 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]]: deposit(cu1, cu2, 20) called.
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "977, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]getCurrentTransaction(): registered with transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//63, BranchQual=] as Synchronization listener with global transaction: <test-pc:4356>:55
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:53, "/cachetest", cu2, 1035)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:53, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:53, "/cachetest", cu1, 987)
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:53, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "987, "true")
      2004-05-11 17:54:01,409 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1035, "true")
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "978, "true")
      2004-05-11 17:54:01,425 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]]: deposit(cu2, cu1, 10) finished. (sum = 3000 = 987 + 1035 + 978)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] runPreparePhase(): run remote prepare with async mode: false commit: false and coordinator: test-pc:4356
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]afterCompletion() called (status=COMMITTED)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): called to commit cache with gtx <test-pc:4356>:53
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): releasing lock org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]commit(): remove local transaction key TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//61, BranchQual=]
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "978, "true")
      2004-05-11 17:54:01,425 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu2, 3) called.
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(5)-192.168.100.120,5,RMI Runtime]getCurrentTransaction(): registered with transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=test-pc//64, BranchQual=] as Synchronization listener with global transaction: <test-pc:4356>:56
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "978, "true")
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:54, "/cachetest", cu3, 961)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:54, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:54, "/cachetest", cu2, 995)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:54, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "987, "true")
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "995, "true")
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu3, "961, "true")
      
      2004-05-11 17:54:01,425 INFO [samples.JBossCacheTestEJB] Thread[Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]]: deposit(cu3, cu2, 17) finished. (sum = 2943 = 987 + 995 + 961)
      
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]afterCompletion() called (status=ROLLEDBACK)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]afterCompletion(): rolling back cache
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]callRemoteMethods(): destination list is empty, discarding call
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]rollback(): called to rollback cache
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:54, "/cachetest", cu2, 1035)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:54, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]_put(<test-pc:4356>:54, "/cachetest", cu3, 978)
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.Node] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]acquired WL: fqn=/cachetest, owner=<test-pc:4356>:54, lock=org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(4)-192.168.100.120,5,RMI Runtime]rollback(): releasing lock org.jboss.cache.lock.IdentityLock@be0446
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu1, "987, "true")
      2004-05-11 17:54:01,425 DEBUG [org.jboss.cache.TreeCache] Thread[RMI TCP Connection(6)-192.168.100.120,5,RMI Runtime]get(, "/cachetest", cu2, "1035, "true")
      
      2004-05-11 17:54:01,425 INFO [STDOUT] java.lang.Exception: sum failure (sum = 2943, cnt = 16)
      ...