1 2 Previous Next 19 Replies Latest reply on Feb 6, 2009 8:47 PM by rs1050

    Far cache problem (3.0.2) tx problems

    rs1050

      Hi,

      I am using 3.0.2 GA. I have a 'far cache' design. What i observed is:

      1. I open JTA tx
      2. write to local cache (which is hooked to remote cache via TcpDelegatingCacheLoader)
      3. write to DB
      4. rollback tx
      5. get value from local cache

      Result:
      1) the far cache is correct, it never gets the value from step 2 which got rolledback
      2)the local cache is *incorrect*, for some reason the value from step 2 remains in that cache, and i can get it from step 5.

      I observed the same results on both JBoss 4.2.3 and Resin 3.1.8

      From the log files I see that the cache is actually aware of the TX being rolled back:

      21:41:43,906 INFO [STDOUT] 21:41:43,906 [http-127.0.0.1-8080-1] DEBUG JtaTransactionManager:processRollback:821 - Initiating transaction rollback
      21:41:43,906 INFO [STDOUT] 21:41:43,906 [http-127.0.0.1-8080-1] INFO TMCacheListener:onNodeTransactioncompleted:24 - : EventImpl{type=TRANSACTION_COMPLETED,pre=false, cache=org.jboss.cache.DataContainerImpl [2nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=TransactionImple < ac, BasicAction: -3f57fe88:11fc:4983ba4b:34 status: ActionStatus.ABORTED >, originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

      Thank you.
      RS.

        • 1. Re: Far cache problem (3.0.2) tx problems
          manik

          What do you mean by rollback tx? How is this performed, and specifically what is the state of the tx (javax.transaction.Status) after step 4?

          Also, which transaction manager do you use?

          I wonder if either (or both of) JBCACHE-1468 or JBCACHE-1469 apply to your case.

          • 2. Re: Far cache problem (3.0.2) tx problems
            rs1050

            I tried using latest 3.0.3 snapshot (from Jan 27) - same problem.

            I am using resin.

            Here is the code (cleanup a bit for readability) from the class UserMangerImpl:

            UserTransaction utx= null;

            Context context = new InitialContext();
            utx = (UserTransaction) context.lookup("java:comp/UserTransaction");
            logger.info("user TX before start of TX: "+utx+", status: "+utx.getStatus());
            utx.begin();
            logger.info("started user TX: "+utx+", status: "+utx.getStatus());

            try {
            //update cache here
            //update db here

            //throw dummy exception here
            throw new RuntimeException("test");

            logger.info("committing tx");
            utx.commit();

            } catch (Exception e) {
            logger.info("rolling back tx");
            utx.rollback();
            }
            logger.info("User TX:"+utx+", status: "+utx.getStatus());


            Here is relevant output (app output removed):

            14:58:33,461 [http--8080-0$20568209] INFO UserManagerImpl:updateUser:58 - user TX before start of TX: UserTransactionProxy[], status: 6

            14:58:33,463 [http--8080-0$20568209] INFO UserManagerImpl:updateUser:63 - started user TX: UserTransactionProxy[], status: 0

            14:58:33,463 [http--8080-0$20568209] DEBUG NearCacheImpl:setValue:53 - setting value for object:/user/1:86 in cacheId:3

            14:58:33,465 [http--8080-0$20568209] INFO TMCacheListener:onNodeTransactionregistered:29 - : EventImpl{type=TRANSACTION_REGISTERED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[01:730c2f36], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

            14:58:33,476 [http--8080-0$20568209] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=true, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=PUT_DATA, data={d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='', _password='sdf{salt}', _email='asdf@xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:730c2f36], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

            14:58:33,492 [http--8080-0$20568209] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=PUT_DATA, data={d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='', _password='sdf{salt}', _email='asdf@xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:730c2f36], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

            14:58:33,572 [http--8080-0$20568209] INFO UserManagerImpl:updateUser:95 - rolling back tx

            14:58:33,574 [http--8080-0$20568209] INFO TMCacheListener:onNodeTransactioncompleted:24 - : EventImpl{type=TRANSACTION_COMPLETED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

            14:58:33,612 [http--8080-0$20568209] INFO UserManagerImpl:updateUser:103 - User TX: UserTransactionProxy[], status: 6


            • 3. Re: Far cache problem (3.0.2) tx problems
              manik

              Could you please enable JBoss Cache TRACE level logging?

              • 4. Re: Far cache problem (3.0.2) tx problems
                rs1050

                my previous post and this one uses resin and 3.0.3 snapshot.

                20:22:31,403 [http--8080-1$21578710] INFO UserManagerImpl:updateUser:58 - user TX before start of TX: UserTransactionProxy[], status: 6
                20:22:31,404 [http--8080-1$21578710] INFO UserManagerImpl:updateUser:63 - started user TX: UserTransactionProxy[], status: 0

                20:22:31,404 [http--8080-1$21578710] DEBUG NearCacheImpl:setValue:53 - setting value for object:/user/1:86 in cacheId:3

                20:22:31,405 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:31,406 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command GetNodeCommand{fqn=/user/1:86} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]

                20:22:31,416 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,417 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:916b5f76] and gtx as null

                20:22:31,418 [http--8080-1$21578710] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$21578710,5,main]

                20:22:31,419 [http--8080-1$21578710] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is null

                20:22:31,443 [http--8080-1$21578710] TRACE TransactionTable:getCurrentTransaction:450 - created new GTX: GlobalTransaction::2, local TX=Transaction[01:916b5f76]

                20:22:31,444 [http--8080-1$21578710] TRACE TxInterceptor:registerTransaction:719 - Registering sync handler for tx Transaction[01:916b5f76], gtx GlobalTransaction::2

                20:22:31,444 [http--8080-1$21578710] TRACE TxInterceptor:registerHandler:744 - registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction::2, tx=com.caucho.transaction.TransactionImpl@20565916))

                20:22:31,459 [http--8080-1$21578710] INFO TMCacheListener:onNodeTransactionregistered:29 - : EventImpl{type=TRANSACTION_REGISTERED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[01:916b5f76], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

                20:22:31,464 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.

                20:22:31,470 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:mustLoad:438 - Don't load [/user/1:86], key requested is null

                20:22:31,471 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false

                20:22:31,472 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.

                20:22:31,473 [http--8080-1$21578710] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.

                20:22:31,474 [http--8080-1$21578710] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /user/1:86 data=[d]]}

                20:22:31,481 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.

                20:22:31,482 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options

                20:22:31,483 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:31,484 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction::2, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}} and InvocationContext [InvocationContext{transaction=Transaction[01:916b5f76], globalTransaction=GlobalTransaction::2, transactionContext=TransactionEntry
                modificationList: null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]

                20:22:31,498 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,499 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:916b5f76] and gtx as GlobalTransaction::2

                20:22:31,500 [http--8080-1$21578710] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$21578710,5,main]

                20:22:31,501 [http--8080-1$21578710] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is GlobalTransaction::2

                20:22:31,516 [http--8080-1$21578710] TRACE TxInterceptor:registerTransaction:732 - Transaction Transaction[01:916b5f76] is already registered.

                20:22:31,517 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.

                20:22:31,517 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:mustLoad:443 - Don't load [/user/1:86], already have necessary key in memory

                20:22:31,518 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86
                mustLoad=false

                20:22:31,534 [http--8080-1$21578710] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86

                20:22:31,536 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForWriting:208 - Retrieving wrapped node /user/1:86
                20:22:31,537 [http--8080-1$21578710] TRACE PutKeyValueCommand:perform:76 - Perform('GlobalTransaction::2', '/user/1:86', k='d', v='TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}')

                20:22:31,551 [http--8080-1$21578710] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=true, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=PUT_DATA, data={d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:916b5f76], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

                20:22:31,561 [http--8080-1$21578710] TRACE PutKeyValueCommand:perform:88 - Old value is TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}, dataLoaded=false

                20:22:31,562 [http--8080-1$21578710] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=PUT_DATA, data={d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:916b5f76], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

                20:22:31,569 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.

                20:22:31,570 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options

                20:22:31,613 [http--8080-1$21578710] INFO XmlBeanDefinitionReader:loadBeanDefinitions:323 - Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]

                20:22:31,639 [http--8080-1$21578710] INFO SQLErrorCodesFactory::128 - SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase]

                20:22:31,646 [http--8080-1$21578710] INFO UserManagerImpl:updateUser:95 - rolling back tx

                20:22:31,646 [http--8080-1$21578710] TRACE TxInterceptor:beforeCompletion:865 - Running beforeCompletion on gtx GlobalTransaction::2
                20:22:31,707 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,707 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:916b5f76] and gtx as GlobalTransaction::2

                20:22:31,708 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:31,708 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,715 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as
                Transaction[01:916b5f76] and gtx as GlobalTransaction::2

                20:22:31,716 [http--8080-1$21578710] TRACE CacheStoreInterceptor:handlePrepareCommand:195 - transactional so don't put stuff in the cloader yet.

                20:22:31,717 [http--8080-1$21578710] TRACE CacheStoreInterceptor:prepareCacheLoader:331 - Cache loader modification list: [PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction::2, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}}]

                20:22:31,727 [http--8080-1$21578710] TRACE CacheStoreInterceptor:prepareCacheLoader:339 - Converted method calls to cache loader modifications. List size: 1

                20:22:31,728 [http--8080-1$21578710] TRACE CallInterceptor:visitPrepareCommand:70 - Suppressing invocation of method handlePrepareCommand.

                20:22:31,729 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.

                20:22:31,730 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,743 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null

                20:22:31,744 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,745 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[] and gtx as GlobalTransaction::2

                20:22:31,745 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:31,753 [http--8080-1$21578710] TRACE TxInterceptor:afterCompletion:917 - calling aftercompletion for GlobalTransaction::2

                20:22:31,759 [http--8080-1$21578710] TRACE TxInterceptor:afterCompletion:940 - Running rollback phase

                20:22:31,760 [http--8080-1$21578710] TRACE TxInterceptor:runRollbackPhase:596 - running rollback for GlobalTransaction::2

                20:22:31,760 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:visitRollbackCommand:218 - Removing temporarily created nodes

                20:22:31,761 [http--8080-1$21578710] TRACE CallInterceptor:visitRollbackCommand:91 - Suppressing invocation of method handleRollbackCommand.

                20:22:31,766 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:cleanupLocks:387 - Releasing lock on [/user/1:86] for owner GlobalTransaction::2

                20:22:31,767 [http--8080-1$21578710] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86

                20:22:31,767 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.

                20:22:31,768 [http--8080-1$21578710] INFO TMCacheListener:onNodeTransactioncompleted:24 - : EventImpl{type=TRANSACTION_COMPLETED,pre=false, cache=org.jboss.cache.DataContainerImpl [2 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}

                20:22:31,779 [http--8080-1$21578710] TRACE TxInterceptor:handleCommitRollback:527 - Finished local commit/rollback method for GlobalTransaction::2

                20:22:31,780 [http--8080-1$21578710] TRACE TxInterceptor:afterCompletion:942 - Finished rollback phase

                20:22:31,781 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:31,781 [http--8080-1$21578710] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null

                20:22:31,782 [http--8080-1$21578710] INFO UserManagerImpl:updateUser:103 - User TX: UserTransactionProxy[], status: 6

                20:22:32,795 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:32,796 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command
                GetNodeCommand{fqn=/user/1:86} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]

                20:22:32,808 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:32,808 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null

                20:22:32,809 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.

                20:22:32,811 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:mustLoad:438 - Don't load [/user/1:86], key requested is null

                20:22:32,817 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false

                20:22:32,817 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.

                20:22:32,818 [http--8080-1$21578710] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.

                20:22:32,819 [http--8080-1$21578710] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /user/1:86 data=[d]]}

                20:22:32,831 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
                20:22:32,832 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options

                20:22:32,833 [http--8080-1$21578710] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.

                20:22:32,833 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command
                GetKeyValueCommand{fqn=/user/1:86, key=d, sendNodeEvent=true} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]

                20:22:32,844 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.

                20:22:32,845 [http--8080-1$21578710] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null

                20:22:32,846 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.

                20:22:32,846 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:mustLoad:443 - Don't load [/user/1:86], already have necessary key in memory
                20:22:32,863 [http--8080-1$21578710] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
                20:22:32,864 [http--8080-1$21578710] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.

                20:22:32,864 [http--8080-1$21578710] TRACE CallInterceptor:handleDefault:98 - Executing command: GetKeyValueCommand{fqn=/user/1:86, key=d, sendNodeEvent=true}.

                20:22:32,865 [http--8080-1$21578710] TRACE GetKeyValueCommand:perform:89 - Found value TMUserImpl{_id=1:86, _username='asdf', _SLUsername='iwre', _password='salt', _email='asdf@xomc.om233', _userStateCd=A}

                20:22:32,876 [http--8080-1$21578710] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
                20:22:32,879 [http--8080-1$21578710] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options

                • 5. Re: Far cache problem (3.0.2) tx problems
                  manik

                  Do you see this with any other cache loader as well, or just the TcpDelegatingCL? Could you try with one of the other CLs?

                  • 6. Re: Far cache problem (3.0.2) tx problems
                    rs1050

                    I tried using jdbc cacheloader with this config:



                    cache.jdbc.table.name=jbosscache
                    cache.jdbc.table.create=true
                    cache.jdbc.table.drop=true
                    cache.jdbc.table.primarykey=jbosscache_pk
                    cache.jdbc.fqn.column=fqn
                    cache.jdbc.fqn.type=VARCHAR(255)
                    cache.jdbc.node.column=node
                    cache.jdbc.node.type=BLOB
                    cache.jdbc.parent.column=parent
                    cache.jdbc.driver=com.mysql.jdbc.Driver
                    cache.jdbc.url=jdbc:mysql://xxxx
                    cache.jdbc.user=xxxx
                    cache.jdbc.password=xxxxx



                    for some reason i got an exception which was absent in TcpDelegating cache loader...

                    20:56:59,384 [http--8080-0$11387974] INFO TestUser:getSomething:13 - yoyo:
                    20:56:59,386 [http--8080-0$11387974] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
                    20:56:59,389 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command GetNodeCommand{fqn=/user/1:86} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]
                    20:57:00,311 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:00,312 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
                    20:57:00,312 [http--8080-0$11387974] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
                    20:57:00,313 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
                    20:57:00,325 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
                    20:57:00,326 [http--8080-0$11387974] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86
                    20:57:00,365 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@c787d7
                    20:57:00,366 [http--8080-0$11387974] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
                    20:57:00,369 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection@c787d7
                    20:57:00,370 [http--8080-0$11387974] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
                    20:57:00,451 [http--8080-0$11387974] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
                    20:57:00,452 [http--8080-0$11387974] TRACE GetNodeCommand:perform:70 - Found node, returning null
                    20:57:00,453 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/user/1:86] for owner Thread[http--8080-0$11387974,5,main]
                    20:57:00,454 [http--8080-0$11387974] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86
                    20:57:00,456 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
                    20:57:00,464 [http--8080-0$11387974] DEBUG NearCacheImpl:getValue:42 - for fqn: /user/1:86 got this value from cache: null
                    20:57:00,465 [http--8080-0$11387974] INFO UserManagerImpl:getUser:113 - user for id: 1:86 NOT found in cache, will get from DB
                    20:57:00,473 [http--8080-0$11387974] DEBUG JtaTransactionManager:lookupTransactionManager:587 - Retrieving JTA TransactionManager from JNDI location [java:/TransactionManager]
                    20:57:00,475 [http--8080-0$11387974] DEBUG JtaTransactionManager:findUserTransaction:676 - JTA UserTransaction found at default JNDI location [java:comp/UserTransaction]
                    20:57:00,480 [http--8080-0$11387974] INFO JtaTransactionManager:checkUserTransactionAndTransactionManager:488 - Using JTA UserTransaction: UserTransactionProxy[]
                    20:57:00,482 [http--8080-0$11387974] INFO JtaTransactionManager:checkUserTransactionAndTransactionManager:499 - Using JTA TransactionManager: TransactionManagerImpl[]
                    20:57:00,490 [http--8080-0$11387974] DEBUG JtaTransactionManager:findTransactionSynchronizationRegistry:777 - JTA 1.1 [javax.transaction.TransactionSynchronizationRegistry] not available
                    20:57:00,868 [http--8080-0$11387974] INFO TestUser:getSomething:19 - updating user with good value: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233712620868', _password='sdf{romanSalt}', _email='asdf@xomc.om233', _userStateCd=A}
                    20:57:00,872 [http--8080-0$11387974] INFO UserManagerImpl:updateUser:54 - user TX before start of TX: UserTransactionProxy[], status: 6
                    20:57:00,873 [http--8080-0$11387974] INFO UserManagerImpl:updateUser:59 - started user TX: UserTransactionProxy[], status: 0
                    20:57:00,873 [http--8080-0$11387974] DEBUG NearCacheImpl:setValue:53 - setting value for object:/user/1:86 in cacheId:3
                    20:57:01,108 [http--8080-0$11387974] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
                    20:57:01,109 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command GetNodeCommand{fqn=/user/1:86} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]
                    20:57:01,121 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:01,121 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:bbb6a9a6] and gtx as null
                    20:57:01,122 [http--8080-0$11387974] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-0$11387974,5,main]
                    20:57:01,123 [http--8080-0$11387974] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is null
                    20:57:01,134 [http--8080-0$11387974] TRACE TransactionTable:getCurrentTransaction:450 - created new GTX: GlobalTransaction::1, local TX=Transaction[01:bbb6a9a6]
                    20:57:01,136 [http--8080-0$11387974] TRACE TxInterceptor:registerTransaction:719 - Registering sync handler for tx Transaction[01:bbb6a9a6], gtx GlobalTransaction::1
                    20:57:01,141 [http--8080-0$11387974] TRACE TxInterceptor:registerHandler:744 - registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction::1, tx=com.caucho.transaction.TransactionImpl@29842687))
                    20:57:01,153 [http--8080-0$11387974] INFO TMCacheListener:onNodeTransactionregistered:29 - : EventImpl{type=TRANSACTION_REGISTERED,pre=false, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,155 [http--8080-0$11387974] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
                    20:57:01,162 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
                    20:57:01,170 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
                    20:57:01,171 [http--8080-0$11387974] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86
                    20:57:01,197 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@26c7da
                    20:57:01,198 [http--8080-0$11387974] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
                    20:57:01,200 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection@26c7da
                    20:57:01,201 [http--8080-0$11387974] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
                    20:57:01,283 [http--8080-0$11387974] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
                    20:57:01,284 [http--8080-0$11387974] TRACE GetNodeCommand:perform:70 - Found node, returning null
                    20:57:01,285 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
                    20:57:01,286 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
                    20:57:01,287 [http--8080-0$11387974] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
                    20:57:01,296 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction::1, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233712620868', _password='sdf{romanSalt}', _email='asdf@xomc.om233', _userStateCd=A}} and InvocationContext [InvocationContext{transaction=Transaction[01:bbb6a9a6], globalTransaction=GlobalTransaction::1, transactionContext=TransactionEntry
                    modificationList: null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]
                    20:57:01,306 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:01,307 [http--8080-0$11387974] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:bbb6a9a6] and gtx as GlobalTransaction::1
                    20:57:01,308 [http--8080-0$11387974] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-0$11387974,5,main]
                    20:57:01,309 [http--8080-0$11387974] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is GlobalTransaction::1
                    20:57:01,321 [http--8080-0$11387974] TRACE TxInterceptor:registerTransaction:732 - Transaction Transaction[01:bbb6a9a6] is already registered.
                    20:57:01,328 [http--8080-0$11387974] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
                    20:57:01,328 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
                    20:57:01,329 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
                    20:57:01,339 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:loadData:494 - Attempting to load data for /user/1:86
                    20:57:01,368 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@13ccea
                    20:57:01,369 [http--8080-0$11387974] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT node FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
                    20:57:01,371 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection@13ccea
                    20:57:01,373 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:loadData:497 - Node /user/1:86 exists? false
                    20:57:01,464 [http--8080-0$11387974] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user
                    20:57:01,466 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_CREATED,pre=true, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=/user, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,470 [http--8080-0$11387974] TRACE MVCCNodeFactory:createChildNode:140 - Created new child with fqn [/user]
                    20:57:01,475 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_CREATED,pre=false, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=/user, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,477 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_CREATED,pre=true, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=/user/1:86, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,485 [http--8080-0$11387974] TRACE MVCCNodeFactory:createChildNode:140 - Created new child with fqn [/user/1:86]
                    20:57:01,486 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_CREATED,pre=false, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=/user/1:86, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,487 [http--8080-0$11387974] TRACE PutKeyValueCommand:perform:76 - Perform('GlobalTransaction::1', '/user/1:86', k='d', v='TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233712620868', _password='sdf{romanSalt}', _email='asdf@xomc.om233', _userStateCd=A}')
                    20:57:01,496 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=true, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=PUT_DATA, data={}, fqn=/user/1:86, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,497 [http--8080-0$11387974] TRACE PutKeyValueCommand:perform:88 - Old value is null, dataLoaded=false
                    20:57:01,499 [http--8080-0$11387974] INFO TMCacheListener:onNodeEvent:41 - : EventImpl{type=NODE_MODIFIED,pre=false, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=PUT_DATA, data={d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233712620868', _password='sdf{romanSalt}', _email='asdf@xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:bbb6a9a6], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:01,511 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
                    20:57:02,116 [http--8080-0$11387974] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
                    20:57:02,131 [http--8080-0$11387974] INFO UserManagerImpl:updateUser:87 - committing tx
                    20:57:02,132 [http--8080-0$11387974] TRACE TxInterceptor:beforeCompletion:865 - Running beforeCompletion on gtx GlobalTransaction::1
                    20:57:02,133 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:02,134 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:bbb6a9a6] and gtx as GlobalTransaction::1
                    20:57:02,139 [http--8080-0$11387974] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
                    20:57:02,140 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:02,140 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:bbb6a9a6] and gtx as GlobalTransaction::1
                    20:57:02,142 [http--8080-0$11387974] TRACE CacheStoreInterceptor:handlePrepareCommand:195 - transactional so don't put stuff in the cloader yet.
                    20:57:02,148 [http--8080-0$11387974] TRACE CacheStoreInterceptor:prepareCacheLoader:331 - Cache loader modification list: [PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction::1, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233712620868', _password='sdf{romanSalt}', _email='asdf@xomc.om233', _userStateCd=A}}]
                    20:57:02,155 [http--8080-0$11387974] TRACE CacheStoreInterceptor:prepareCacheLoader:339 - Converted method calls to cache loader modifications. List size: 1
                    20:57:02,192 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@12c9015
                    20:57:02,198 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:prepare:83 - opened tx connection: tx=GlobalTransaction::1, con=com.mysql.jdbc.JDBC4Connection@12c9015
                    20:57:02,200 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@12c9015
                    20:57:02,201 [http--8080-0$11387974] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT node FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
                    20:57:02,284 [http--8080-0$11387974] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@12c9015
                    20:57:02,285 [http--8080-0$11387974] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [INSERT INTO jbosscache (fqn, node, parent) SELECT ?, ?, ? FROM jbosscache_D WHERE NOT EXISTS (SELECT fqn FROM jbosscache WHERE fqn = ?)]
                    20:57:02,286 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
                    20:57:02,295 [http--8080-0$11387974] WARN TxInterceptor:beforeCompletion:1083 - Caught exception, will now set transaction to roll back
                    java.lang.NullPointerException
                    at org.jboss.cache.marshall.VersionAwareMarshaller.objectToObjectStream(VersionAwareMarshaller.java:334)
                    at org.jboss.cache.marshall.VersionAwareMarshaller.objectToBuffer(VersionAwareMarshaller.java:179)
                    at org.jboss.cache.loader.AdjListJDBCCacheLoader.marshall(AdjListJDBCCacheLoader.java:781)
                    at org.jboss.cache.loader.AdjListJDBCCacheLoader.populatePreparedStatementForInsert(AdjListJDBCCacheLoader.java:560)
                    at org.jboss.cache.loader.AdjListJDBCCacheLoader.insertNode(AdjListJDBCCacheLoader.java:525)
                    at org.jboss.cache.loader.JDBCCacheLoader.addNewSubtree(JDBCCacheLoader.java:348)
                    at org.jboss.cache.loader.JDBCCacheLoader.put(JDBCCacheLoader.java:108)
                    at org.jboss.cache.loader.AbstractCacheLoader.put(AbstractCacheLoader.java:303)
                    at org.jboss.cache.loader.AdjListJDBCCacheLoader.prepare(AdjListJDBCCacheLoader.java:251)
                    at org.jboss.cache.interceptors.CacheStoreInterceptor.prepareCacheLoader(CacheStoreInterceptor.java:343)
                    at org.jboss.cache.interceptors.CacheStoreInterceptor.handlePrepareCommand(CacheStoreInterceptor.java:196)
                    at org.jboss.cache.interceptors.base.SkipCheckChainedInterceptor.visitPrepareCommand(SkipCheckChainedInterceptor.java:310)
                    at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:68)
                    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                    at org.jboss.cache.interceptors.MVCCLockingInterceptor.handlePrepareCommand(MVCCLockingInterceptor.java:328)
                    at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitPrepareCommand(PrePostProcessingCommandInterceptor.java:383)
                    at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:68)
                    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                    at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
                    at org.jboss.cache.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:140)
                    at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:68)
                    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                    at org.jboss.cache.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:50)
                    at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:68)
                    at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
                    at org.jboss.cache.interceptors.TxInterceptor.runPreparePhase(TxInterceptor.java:648)
                    at org.jboss.cache.interceptors.TxInterceptor$LocalSynchronizationHandler.beforeCompletion(TxInterceptor.java:1065)
                    at org.jboss.cache.interceptors.OrderedSynchronizationHandler.beforeCompletion(OrderedSynchronizationHandler.java:81)
                    at com.caucho.transaction.TransactionImpl.callBeforeCompletion(TransactionImpl.java:843)
                    at com.caucho.transaction.TransactionImpl.commit(TransactionImpl.java:582)
                    at com.caucho.transaction.TransactionManagerImpl.commit(TransactionManagerImpl.java:271)
                    at com.caucho.jca.UserTransactionImpl.commit(UserTransactionImpl.java:436)
                    at com.caucho.jca.UserTransactionProxy.commit(UserTransactionProxy.java:167)
                    at com.threadmap.site.user.impl.UserManagerImpl.updateUser(UserManagerImpl.java:88)
                    at com.threadmap.tapestry.pages.user.TestUser.getSomething(TestUser.java:20)
                    at $PropertyConduit_11f3f0052bc.get($PropertyConduit_11f3f0052bc.java)
                    at org.apache.tapestry5.internal.bindings.PropBinding.get(PropBinding.java:53)
                    at org.apache.tapestry5.internal.structure.ExpansionPageElement.render(ExpansionPageElement.java:47)
                    at org.apache.tapestry5.internal.services.RenderQueueImpl.run(RenderQueueImpl.java:72)
                    at org.apache.tapestry5.internal.services.PageRenderQueueImpl.render(PageRenderQueueImpl.java:121)
                    at $PageRenderQueue_11f3f0052c3.render($PageRenderQueue_11f3f0052c3.java)
                    at $PageRenderQueue_11f3f0052c1.render($PageRenderQueue_11f3f0052c1.java)
                    at org.apache.tapestry5.services.TapestryModule$19.renderMarkup(TapestryModule.java:1200)
                    at org.apache.tapestry5.services.TapestryModule$29.renderMarkup(TapestryModule.java:1580)
                    at $MarkupRenderer_11f3f0052c7.renderMarkup($MarkupRenderer_11f3f0052c7.java)
                    at org.apache.tapestry5.services.TapestryModule$28.renderMarkup(TapestryModule.java:1561)
                    at $MarkupRenderer_11f3f0052c7.renderMarkup($MarkupRenderer_11f3f0052c7.java)
                    at org.apache.tapestry5.services.TapestryModule$27.renderMarkup(TapestryModule.java:1543)
                    at $MarkupRenderer_11f3f0052c7.renderMarkup($MarkupRenderer_11f3f0052c7.java)
                    at org.apache.tapestry5.services.TapestryModule$26.renderMarkup(TapestryModule.java:1525)
                    at $MarkupRenderer_11f3f0052c7.renderMarkup($MarkupRenderer_11f3f0052c7.java)
                    at org.apache.tapestry5.services.TapestryModule$25.renderMarkup(TapestryModule.java:1495)
                    at $MarkupRenderer_11f3f0052c7.renderMarkup($MarkupRenderer_11f3f0052c7.java)
                    at $MarkupRenderer_11f3f0052c0.renderMarkup($MarkupRenderer_11f3f0052c0.java)
                    at org.apache.tapestry5.internal.services.PageMarkupRendererImpl.renderPageMarkup(PageMarkupRendererImpl.java:64)
                    at $PageMarkupRenderer_11f3f0052be.renderPageMarkup($PageMarkupRenderer_11f3f0052be.java)
                    at org.apache.tapestry5.internal.services.PageResponseRendererImpl.renderPageResponse(PageResponseRendererImpl.java:57)
                    at $PageResponseRenderer_11f3f005293.renderPageResponse($PageResponseRenderer_11f3f005293.java)
                    at org.apache.tapestry5.internal.services.PageRenderRequestHandlerImpl.handle(PageRenderRequestHandlerImpl.java:59)
                    at org.apache.tapestry5.services.TapestryModule$35.handle(TapestryModule.java:1779)
                    at $PageRenderRequestHandler_11f3f005294.handle($PageRenderRequestHandler_11f3f005294.java)
                    at $PageRenderRequestHandler_11f3f005287.handle($PageRenderRequestHandler_11f3f005287.java)
                    at org.apache.tapestry5.internal.services.PageRenderDispatcher.process(PageRenderDispatcher.java:92)
                    at org.apache.tapestry5.internal.services.PageRenderDispatcher.dispatch(PageRenderDispatcher.java:71)
                    at $Dispatcher_11f3f00528d.dispatch($Dispatcher_11f3f00528d.java)
                    at $Dispatcher_11f3f005280.dispatch($Dispatcher_11f3f005280.java)
                    at org.apache.tapestry5.services.TapestryModule$17.service(TapestryModule.java:1029)
                    at com.threadmap.tapestry.services.AppModule$1.service(AppModule.java:105)
                    at $RequestFilter_11f3f00527f.service($RequestFilter_11f3f00527f.java)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.internal.services.LocalizationFilter.service(LocalizationFilter.java:42)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.internal.services.RequestErrorFilter.service(RequestErrorFilter.java:26)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.services.TapestryModule$3.service(TapestryModule.java:621)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.services.TapestryModule$2.service(TapestryModule.java:611)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.internal.services.StaticFilesFilter.service(StaticFilesFilter.java:85)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at org.apache.tapestry5.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:93)
                    at org.apache.tapestry5.internal.services.CheckForUpdatesFilter$2.invoke(CheckForUpdatesFilter.java:84)
                    at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
                    at org.apache.tapestry5.internal.services.CheckForUpdatesFilter.service(CheckForUpdatesFilter.java:106)
                    at $RequestHandler_11f3f005281.service($RequestHandler_11f3f005281.java)
                    at $RequestHandler_11f3f005277.service($RequestHandler_11f3f005277.java)
                    at org.apache.tapestry5.services.TapestryModule$16.service(TapestryModule.java:1007)
                    at org.apache.tapestry5.upload.internal.services.MultipartServletRequestFilter.service(MultipartServletRequestFilter.java:44)
                    at $HttpServletRequestHandler_11f3f005278.service($HttpServletRequestHandler_11f3f005278.java)
                    at org.apache.tapestry5.internal.services.IgnoredPathsFilter.service(IgnoredPathsFilter.java:62)
                    at $HttpServletRequestFilter_11f3f005276.service($HttpServletRequestFilter_11f3f005276.java)
                    at $HttpServletRequestHandler_11f3f005278.service($HttpServletRequestHandler_11f3f005278.java)
                    at $HttpServletRequestHandler_11f3f005274.service($HttpServletRequestHandler_11f3f005274.java)
                    at org.apache.tapestry5.TapestryFilter.doFilter(TapestryFilter.java:179)
                    at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:87)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378)
                    at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
                    at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.SessionFixationProtectionFilter.doFilterHttp(SessionFixationProtectionFilter.java:52)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.rememberme.RememberMeProcessingFilter.doFilterHttp(RememberMeProcessingFilter.java:109)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
                    at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
                    at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
                    at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
                    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:236)
                    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
                    at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:87)
                    at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:187)
                    at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:265)
                    at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:273)
                    at com.caucho.server.port.TcpConnection.run(TcpConnection.java:682)
                    at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:730)
                    at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:649)
                    at java.lang.Thread.run(Thread.java:619)
                    20:57:02,495 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:02,496 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
                    20:57:02,497 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:02,497 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[] and gtx as GlobalTransaction::1
                    20:57:02,572 [http--8080-0$11387974] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
                    20:57:03,084 [http--8080-0$11387974] TRACE TxInterceptor:afterCompletion:917 - calling aftercompletion for GlobalTransaction::1
                    20:57:03,085 [http--8080-0$11387974] TRACE TxInterceptor:afterCompletion:940 - Running rollback phase
                    20:57:03,085 [http--8080-0$11387974] TRACE TxInterceptor:runRollbackPhase:596 - running rollback for GlobalTransaction::1
                    20:57:03,086 [http--8080-0$11387974] TRACE CacheLoaderInterceptor:visitRollbackCommand:218 - Removing temporarily created nodes
                    20:57:03,205 [http--8080-0$11387974] TRACE CallInterceptor:visitRollbackCommand:91 - Suppressing invocation of method handleRollbackCommand.
                    20:57:03,206 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:cleanupLocks:387 - Releasing lock on [/user] for owner GlobalTransaction::1
                    20:57:03,207 [http--8080-0$11387974] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user
                    20:57:03,207 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:cleanupLocks:387 - Releasing lock on [/user/1:86] for owner GlobalTransaction::1
                    20:57:03,219 [http--8080-0$11387974] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86
                    20:57:03,220 [http--8080-0$11387974] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
                    20:57:03,221 [http--8080-0$11387974] INFO TMCacheListener:onNodeTransactioncompleted:24 - : EventImpl{type=TRANSACTION_COMPLETED,pre=false, cache=org.jboss.cache.DataContainerImpl [0 nodes, 0 locks], modificationType=null, data=null, fqn=null, transaction=Transaction[], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
                    20:57:03,228 [http--8080-0$11387974] TRACE TxInterceptor:handleCommitRollback:527 - Finished local commit/rollback method for GlobalTransaction::1
                    20:57:03,229 [http--8080-0$11387974] TRACE TxInterceptor:afterCompletion:942 - Finished rollback phase
                    20:57:03,230 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
                    20:57:03,231 [http--8080-0$11387974] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
                    20:57:03,231 [http--8080-0$11387974] INFO UserManagerImpl:updateUser:91 - rolling back tx

                    • 7. Re: Far cache problem (3.0.2) tx problems
                      manik

                      Could you please paste the full loaders config element, using the code button?

                      • 8. Re: Far cache problem (3.0.2) tx problems
                        rs1050

                        the first one (commented out) is the only i had when reporting the error at the beginning of this thread.

                        <loaders passivation="false" shared="false">
                         <!--<loader class="org.jboss.cache.loader.TcpDelegatingCacheLoader"-->
                         <!--async="false"-->
                         <!--fetchPersistentState="true"-->
                         <!--ignoreModifications="false"-->
                         <!--purgeOnStartup="false">-->
                         <!--<properties>-->
                         <!--host=127.0.0.1-->
                         <!--port=7500-->
                         <!--timeout=100000-->
                         <!--reconnectWaitTime=2000-->
                         <!--</properties>-->
                         <!--</loader>-->
                        
                         <loader class="org.jboss.cache.loader.JDBCCacheLoader" async="false" fetchPersistentState="true"
                         ignoreModifications="false" purgeOnStartup="false">
                         <properties>
                         cache.jdbc.table.name=jbosscache
                         cache.jdbc.table.create=true
                         cache.jdbc.table.drop=true
                         cache.jdbc.table.primarykey=jbosscache_pk
                         cache.jdbc.fqn.column=fqn
                         cache.jdbc.fqn.type=VARCHAR(255)
                         cache.jdbc.node.column=node
                         cache.jdbc.node.type=BLOB
                         cache.jdbc.parent.column=parent
                         cache.jdbc.driver=com.mysql.jdbc.Driver
                         cache.jdbc.url=jdbc:mysql://white/threadmap
                         cache.jdbc.user=threadmap_dev
                         cache.jdbc.password=75eGK%
                         </properties>
                         </loader>
                         </loaders>
                        


                        • 9. Re: Far cache problem (3.0.2) tx problems
                          manik

                          Try setting fetchPersistentState to false, with the JDBC CL and see if you have the error.

                          • 10. Re: Far cache problem (3.0.2) tx problems
                            rs1050

                            still getting same exception, same line on VersionAwareMarshaller (334)

                            • 11. Re: Far cache problem (3.0.2) tx problems
                              rs1050

                              still getting same exception, same line on VersionAwareMarshaller (334)

                              • 12. Re: Far cache problem (3.0.2) tx problems
                                rs1050

                                sorry for posting twice, i thought the first post got lost

                                • 13. Re: Far cache problem (3.0.2) tx problems
                                  rs1050

                                  Is there anything that i can try or provide to help investigation? This is an important bug for us.

                                  Thank you.
                                  RS.

                                  • 14. Re: Far cache problem (3.0.2) tx problems
                                    manik

                                    If your case is that urgent I would suggest you use the customer support portal for more timely help.

                                    Anyway, have you enabled region based marshalling?

                                    1 2 Previous Next