1 2 Previous Next 23 Replies Latest reply on Jan 27, 2009 9:47 AM by Eduardo Martins

    tx aware cache config issue

    Eduardo Martins Apprentice

      Hi, we are finally migrating Mobicents JAIN SLEE server (from XACache) to JBoss Cache 3 and I'm having an issue, consider this code:

       Fqn fqn = Fqn.fromElements("short test");
       try {
       begin();
       setRollbackOnly();
       cache.getRoot().addChild(fqn);
       commit();
       begin();
       if (cache.getRoot().hasChild(fqn)) {
       logger.info("BIGGGGGGGGGGGGGGG ISSSSSSSSSSSSSSSSSSSSUEEEEEEEEEE");
       }
       commit();
       }
       catch (Exception e) {
       logger.error(e.getMessage(),e);
       }
      


      The method names have the meaning of the same named jta tx manager operations.

      The issue is that if setRollbackOnly() then jboss cache adds the node to cache, how can I avoid this and make jboss cache only tx aware and don't commit changes when no tx is in active or preparing state?

      Thanks in advance.

      -- Eduardo

        • 1. Re: tx aware cache config issue
          Manik Surtani Master

          What does your setRollbackOnly() method do? Also, what does your begin() and commit() methods do? Could I see their implementation?

          As long as these delegate to a Transaction or UserTransaction object, and these transactions are obtained from the *same* TransactionManager instance you have registered with the cache, all should work.

          Also, do you have a debug log for the cache?

          • 2. Re: tx aware cache config issue
            Eduardo Martins Apprentice

             

            
             public void begin() throws SystemException {
            
             Transaction tx = getTransaction();
            
             // check there is no transaction
             if (tx != null) {
             throw new SystemException("Transaction already started, cannot nest tx. Ongoing Tx: "+ tx);
             }
            
             // begin transaction
             try {
             transactionManager.begin();
             } catch (NotSupportedException e) {
             throw new SystemException("Failed to begin transaction." + e);
             }
            
             tx = getTransaction();
            
             if (logger.isDebugEnabled()) {
             logger.debug("Transaction started: "+tx);
             }
            
             // register for call-backs
             try {
             tx.registerSynchronization(new SynchronizationHandler(tx));
             } catch (RollbackException e) {
             throw new SystemException("Unable to register listener for created transaction. Error: "+e.getMessage());
             }
             }
            
             public void commit() throws SystemException {
            
             Transaction tx = getTransaction();
            
             if (tx == null) {
             throw new SystemException(
             "Failed to commit transaction since there is no transaction to commit!");
             }
            
             if (getRollbackOnly()) {
             if (logger.isDebugEnabled())
             logger
             .debug("Transaction marked for roll back, cannot commit, ending with rollback: "
             + tx);
             rollback();
             } else if (tx.getStatus() == Status.STATUS_ACTIVE) {
             try {
             transactionManager.commit();
             if (logger.isDebugEnabled())
             logger.debug("Committed tx "+tx);
             } catch (Exception e) {
             throw new SystemException("Failed to commit tx " + tx + ". Error: "
             + e.getMessage());
             }
             } else {
             throw new SystemException(
             "Failed to commit transaction "+tx+" since state is "
             + tx.getStatus());
             }
             }
            
            
             public boolean getRollbackOnly() throws SystemException {
            
             Transaction tx = getTransaction();
            
             if (tx == null) {
             throw new SystemException("no transaction");
             }
            
             return tx.getStatus() == Status.STATUS_MARKED_ROLLBACK;
             }
            
             public Transaction getTransaction() {
            
             if (transactionManager != null) {
             try {
             return transactionManager.getTransaction();
             } catch (SystemException e) {
             throw new RuntimeException(
             "Failed to obtain active JTA transaction");
             }
             }
             else {
             throw new RuntimeException("tx manager unavailable");
             }
             }
            
            
             public void rollback() throws SystemException {
            
             Transaction tx = getTransaction();
            
             if (tx == null) {
             throw new SystemException(
             "Failed to rollback transaction since there is no transaction to rollback!");
             }
            
             if (!((tx.getStatus() != Status.STATUS_ACTIVE) || (tx.getStatus() != Status.STATUS_MARKED_ROLLBACK))) {
             throw new SystemException(
             "Failed to rollback transaction since transaction is in state: "
             + tx.getStatus());
             }
            
             transactionManager.rollback();
            
             if (logger.isDebugEnabled()) {
             logger.debug("Rollbacked tx "+tx);
             }
             }
            
             public void setRollbackOnly() throws SystemException {
            
             if (transactionManager != null) {
             transactionManager.setRollbackOnly();
             if (logger.isDebugEnabled())
             logger.debug("rollbackonly set on tx "
             + getTransaction());
             }
             else {
             throw new SystemException("tx manager unavailable");
             }
             }
            
            


            The methods just delegate to JTA Tx Manager, in this case the RealTransactionManager bean from JBossAS 5.

            Debug logs with 3.0.2.GA:

            13:39:46,655 DEBUG [InterceptorChain] Interceptor chain is: InterceptorChain{
             >> org.jboss.cache.interceptors.CallInterceptor
             >> org.jboss.cache.interceptors.MVCCLockingInterceptor
             >> org.jboss.cache.interceptors.NotificationInterceptor
             >> org.jboss.cache.interceptors.TxInterceptor
             >> org.jboss.cache.interceptors.CacheMgmtInterceptor
             >> org.jboss.cache.interceptors.InvocationContextInterceptor
            }
            13:39:46,655 DEBUG [RegionManagerImpl] Not using an EvictionPolicy
            13:39:46,679 DEBUG [VersionAwareMarshaller] Started with version 3.0.2 and versionInt 30
            13:39:46,679 DEBUG [VersionAwareMarshaller] Using default marshaller class class org.jboss.cache.marshall.CacheMarshaller300
            13:39:46,679 DEBUG [DataContainerImpl] Setting rootInternal to UnversionedNode[ /]
            13:39:46,707 DEBUG [JmxRegistrationManager] Base name is: jboss.cache:service=JBossCache,uniqueId=69b249
            13:39:46,735 INFO [PlatformMBeanServerRegistration] JBossCache MBeans were successfully registered to the platform mbean server.
            13:39:46,737 DEBUG [RPCManagerImpl] cache mode is local, will not create the channel
            13:39:46,737 INFO [ComponentRegistry] JBoss Cache version: JBossCache 'Naga' 3.0.2.GA
            13:39:46,761 DEBUG [SleeTransactionManagerImpl] Transaction started: TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:9 status: ActionStatus.RUNNING >
            13:39:46,764 DEBUG [SleeTransactionManagerImpl] rollbackonly set on tx TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:9 status: ActionStatus.ABORT_ONLY >
            13:39:46,772 DEBUG [SleeTransactionManagerImpl] Transaction marked for roll back, cannot commit, ending with rollback: TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:9 status: ActionStatus.ABORT_ONLY >
            13:39:46,773 DEBUG [SleeTransactionManagerImpl] Rollbacked tx TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:9 status: ActionStatus.ABORTED >
            13:39:46,773 DEBUG [SleeTransactionManagerImpl] Transaction started: TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:b status: ActionStatus.RUNNING >
            13:39:46,786 INFO [SleeTransactionManagerImpl] BIGGGGGGGGGGGGGGG ISSSSSSSSSSSSSSSSSSSSUEEEEEEEEEE
            13:39:46,787 DEBUG [SleeTransactionManagerImpl] beforeCompletion for tx TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:b status: ActionStatus.RUNNING >
            13:39:46,787 DEBUG [SleeTransactionManagerImpl] Committed tx TransactionImple < ac, BasicAction: -53e0fec0:d852:4977259f:b status: ActionStatus.COMMITTED >
            


            Another failing similar scenario:

            Fqn fqn = Fqn.fromElements("short test");
             Object key = new Object();
             Object value = new Object();
             try {
             begin();
             cache.getRoot().addChild(fqn);
             commit();
             begin();
             setRollbackOnly();
             cache.getRoot().getChild(fqn).put(key, value);
             rollback();
             begin();
             if (cache.getRoot().getChild(fqn).get(key) != null) {
             logger.info("BIGGGGGGGGGGGGGGG ISSSSSSSSSSSSSSSSSSSSUEEEEEEEEEE");
             }
             commit();
             }
             catch (Exception e) {
             logger.error(e.getMessage(),e);
             }
            


            And its debug logs with 3.0.2.GA:

            13:54:48,123 DEBUG [DataContainerImpl] Setting rootInternal to NodeReference{delegate=UnversionedNode[ /]}
            13:54:48,149 DEBUG [InterceptorChain] Interceptor chain is: InterceptorChain{
             >> org.jboss.cache.interceptors.CallInterceptor
             >> org.jboss.cache.interceptors.MVCCLockingInterceptor
             >> org.jboss.cache.interceptors.NotificationInterceptor
             >> org.jboss.cache.interceptors.TxInterceptor
             >> org.jboss.cache.interceptors.CacheMgmtInterceptor
             >> org.jboss.cache.interceptors.InvocationContextInterceptor
            }
            13:54:48,149 DEBUG [RegionManagerImpl] Not using an EvictionPolicy
            13:54:48,171 DEBUG [VersionAwareMarshaller] Started with version 3.0.2 and versionInt 30
            13:54:48,171 DEBUG [VersionAwareMarshaller] Using default marshaller class class org.jboss.cache.marshall.CacheMarshaller300
            13:54:48,171 DEBUG [DataContainerImpl] Setting rootInternal to UnversionedNode[ /]
            13:54:48,197 DEBUG [JmxRegistrationManager] Base name is: jboss.cache:service=JBossCache,uniqueId=8163c
            13:54:48,224 INFO [PlatformMBeanServerRegistration] JBossCache MBeans were successfully registered to the platform mbean server.
            13:54:48,225 DEBUG [RPCManagerImpl] cache mode is local, will not create the channel
            13:54:48,225 INFO [ComponentRegistry] JBoss Cache version: JBossCache 'Naga' 3.0.2.GA
            13:54:48,240 DEBUG [SleeTransactionManagerImpl] Transaction started: TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:9 status: ActionStatus.RUNNING >
            13:54:48,268 DEBUG [SleeTransactionManagerImpl] beforeCompletion for tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:9 status: ActionStatus.RUNNING >
            13:54:48,269 DEBUG [SleeTransactionManagerImpl] Committed tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:9 status: ActionStatus.COMMITTED >
            13:54:48,274 DEBUG [SleeTransactionManagerImpl] Transaction started: TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:c status: ActionStatus.RUNNING >
            13:54:48,274 DEBUG [SleeTransactionManagerImpl] rollbackonly set on tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:c status: ActionStatus.ABORT_ONLY >
            13:54:48,274 WARN [TransactionTable] status is 1 (not ACTIVE or PREPARING); returning null)
            13:54:48,275 DEBUG [SleeTransactionManagerImpl] Rollbacked tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:c status: ActionStatus.ABORTED >
            13:54:48,275 DEBUG [SleeTransactionManagerImpl] Transaction started: TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:e status: ActionStatus.RUNNING >
            13:54:48,276 INFO [SleeTransactionManagerImpl] BIGGGGGGGGGGGGGGG ISSSSSSSSSSSSSSSSSSSSUEEEEEEEEEE
            13:54:48,276 DEBUG [SleeTransactionManagerImpl] beforeCompletion for tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:e status: ActionStatus.RUNNING >
            13:54:48,276 DEBUG [SleeTransactionManagerImpl] Committed tx TransactionImple < ac, BasicAction: -53e0fec0:d8d2:49772925:e status: ActionStatus.COMMITTED >
            


            Btw, same behavior with 3.0.1.GA

            Configuration is pretty much default:

            <!-- JBOSS CACHE 3 -->
            
             <bean name="MobicentsCacheConfig" class="org.jboss.cache.config.Configuration">
             <property name="runtimeConfig">
             <bean name="MobicentsCacheRuntimeConfig" class="org.jboss.cache.config.RuntimeConfig">
             <property name="transactionManager">
             <inject bean="RealTransactionManager"/>
             </property>
             </bean>
             </property>
             </bean>
            
             <!-- Factory to build the Cache. -->
             <bean name="MobicentsCacheFactory" class="org.jboss.cache.DefaultCacheFactory">
             <constructor factoryClass="org.jboss.cache.DefaultCacheFactory" factoryMethod="getInstance" />
             </bean>
            
             <!-- The cache itself -->
             <bean name="MobicentsCache" class="org.jboss.cache.Cache">
             <constructor factoryMethod="createCache">
             <factory bean="MobicentsCacheFactory"/>
             <parameter class="org.jboss.cache.config.Configuration"><inject bean="MobicentsCacheConfig"/></parameter>
             <parameter class="boolean">false</parameter>
             </constructor>
             </bean>
            


            --Eduardo

            • 3. Re: tx aware cache config issue
              Manik Surtani Master

              Eduardo,

              Your debug logs don't have any debug messages from JBoss Cache after your transaction starts. This is very odd. Could you perhaps try TRACE level logging for JBC?

              Cheers
              Manik

              • 4. Re: tx aware cache config issue
                Eduardo Martins Apprentice

                Trace logs for the last scenario:

                17:16:11,715 INFO [ComponentRegistry] JBoss Cache version: JBossCache 'Naga' 3.0.2.GA
                17:16:11,737 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,737 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/} 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}]
                17:16:11,738 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,739 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as null
                17:16:11,740 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,740 TRACE [TxInterceptor] Associated gtx in txTable is null
                17:16:11,746 TRACE [TransactionTable] created new GTX: GlobalTransaction:<null>:1, local TX=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING >
                17:16:11,746 TRACE [TxInterceptor] Registering sync handler for tx TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING >, gtx GlobalTransaction:<null>:1
                17:16:11,749 TRACE [TxInterceptor] registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:1, tx=com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@1322016))
                17:16:11,751 TRACE [MVCCNodeHelper] Node / is not in context, fetching from container.
                17:16:11,751 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/}.
                17:16:11,752 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ /]
                17:16:11,752 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,752 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,752 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,754 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/short test} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING >, globalTransaction=GlobalTransaction:<null>: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}]
                17:16:11,754 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,754 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:1
                17:16:11,754 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,754 TRACE [TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
                17:16:11,754 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > is already registered.
                17:16:11,754 TRACE [MVCCNodeHelper] Node /short test is not in context, fetching from container.
                17:16:11,754 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/short test}.
                17:16:11,754 TRACE [GetNodeCommand] Node of type [NullMarkerNode] found but marked as deleted in current scope. Returning null.
                17:16:11,754 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,754 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,755 TRACE [NodeInvocationDelegate] Child is null; creating.
                17:16:11,755 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,756 TRACE [InvocationContextInterceptor] Invoked with command PutDataMapCommand{fqn=/short test, dataVersion=null, data=null, globalTransaction=null, erase=false} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING >, globalTransaction=GlobalTransaction:<null>: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}]
                17:16:11,756 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,756 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:1
                17:16:11,756 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,756 TRACE [TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
                17:16:11,756 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > is already registered.
                17:16:11,756 TRACE [MVCCNodeHelper] Retrieving wrapped node /
                17:16:11,757 TRACE [MVCCLockManager] Attempting to lock /short test
                17:16:11,758 TRACE [MVCCNodeFactory] Created new child with fqn [/short test]
                17:16:11,759 TRACE [PutDataMapCommand] perform(null, "/short test", null)
                17:16:11,759 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,759 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,759 TRACE [NodeInvocationDelegate] Created. Now getting again.
                17:16:11,759 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,760 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/short test} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING >, globalTransaction=GlobalTransaction:<null>:1, transactionContext=TransactionEntry
                modificationList: [PutDataMapCommand{fqn=/short test, dataVersion=null, data=null, globalTransaction=null, erase=false}], optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}]
                17:16:11,760 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,760 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:1
                17:16:11,760 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,760 TRACE [TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
                17:16:11,760 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > is already registered.
                17:16:11,760 TRACE [MVCCNodeHelper] Node /short test is already in context.
                17:16:11,760 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/short test}.
                17:16:11,760 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ /short test]
                17:16:11,760 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,760 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,760 TRACE [NodeInvocationDelegate] Got child UnversionedNode[ /short test]
                17:16:11,761 TRACE [TxInterceptor] Running beforeCompletion on gtx GlobalTransaction:<null>:1
                17:16:11,761 TRACE [TxInterceptor] Setting up transactional context.
                17:16:11,761 TRACE [TxInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:1
                17:16:11,761 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,761 TRACE [TxInterceptor] Setting up transactional context.
                17:16:11,761 TRACE [TxInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:1
                17:16:11,762 TRACE [CallInterceptor] Suppressing invocation of method handlePrepareCommand.
                17:16:11,762 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,762 TRACE [TxInterceptor] Setting up transactional context.
                17:16:11,762 TRACE [TxInterceptor] Setting tx as null and gtx as null
                17:16:11,763 TRACE [TxInterceptor] Setting up transactional context.
                17:16:11,763 TRACE [TxInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:9 status: ActionStatus.COMMITTED > and gtx as GlobalTransaction:<null>:1
                17:16:11,763 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,763 TRACE [TxInterceptor] calling aftercompletion for GlobalTransaction:<null>:1
                17:16:11,763 TRACE [TxInterceptor] Running commit phase. One phase? false
                17:16:11,763 TRACE [TxInterceptor] Running commit for GlobalTransaction:<null>:1
                17:16:11,763 TRACE [CallInterceptor] Suppressing invocation of method handleCommitCommand.
                17:16:11,763 TRACE [ReadCommittedNode] Updating node [/short test]. deleted=false valid=true changed=true created=true
                17:16:11,763 TRACE [MVCCLockingInterceptor] Releasing lock on [/short test] for owner GlobalTransaction:<null>:1
                17:16:11,763 TRACE [MVCCLockManager] Attempting to unlock /short test
                17:16:11,764 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,764 TRACE [TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<null>:1
                17:16:11,764 TRACE [TxInterceptor] Finished commit phase
                17:16:11,764 TRACE [TxInterceptor] Setting up transactional context.
                17:16:11,764 TRACE [TxInterceptor] Setting tx as null and gtx as null
                17:16:11,764 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,764 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/} 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}]
                17:16:11,764 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,764 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > and gtx as null
                17:16:11,764 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,764 TRACE [TxInterceptor] Associated gtx in txTable is null
                17:16:11,765 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > is already registered.
                17:16:11,765 TRACE [MVCCNodeHelper] Node / is not in context, fetching from container.
                17:16:11,765 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/}.
                17:16:11,767 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ / children=[short test]]
                17:16:11,767 TRACE [MVCCLockingInterceptor] Nothing to do since there are no modifications in scope.
                17:16:11,767 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,767 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,767 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/short test} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY >, 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}]
                17:16:11,768 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,768 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > and gtx as null
                17:16:11,768 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,768 TRACE [TxInterceptor] Associated gtx in txTable is null
                17:16:11,768 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > is already registered.
                17:16:11,768 TRACE [MVCCNodeHelper] Node /short test is not in context, fetching from container.
                17:16:11,768 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/short test}.
                17:16:11,768 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ /short test]
                17:16:11,768 TRACE [MVCCLockingInterceptor] Nothing to do since there are no modifications in scope.
                17:16:11,768 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,768 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,768 WARN [TransactionTable] status is 1 (not ACTIVE or PREPARING); returning null)
                17:16:11,769 TRACE [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{fqn=/short test, dataVersion=null, globalTransaction=null, key=java.lang.Object@ca88b3, value=java.lang.Object@d4a2bd} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY >, 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}]
                17:16:11,769 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,769 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > and gtx as null
                17:16:11,769 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,769 TRACE [TxInterceptor] Associated gtx in txTable is null
                17:16:11,769 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY > is already registered.
                17:16:11,769 TRACE [MVCCLockManager] Attempting to lock /short test
                17:16:11,769 TRACE [PutKeyValueCommand] Perform('null', '/short test', k='java.lang.Object@ca88b3', v='java.lang.Object@d4a2bd')
                17:16:11,769 TRACE [PutKeyValueCommand] Old value is null, dataLoaded=false
                17:16:11,769 TRACE [ReadCommittedNode] Updating node [/short test]. deleted=false valid=true changed=true created=false
                17:16:11,769 TRACE [MVCCLockingInterceptor] Releasing lock on [/short test] for owner Thread[main,5,jboss]
                17:16:11,769 TRACE [MVCCLockManager] Attempting to unlock /short test
                17:16:11,769 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,769 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,770 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORTED >, 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}]
                17:16:11,770 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,770 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING > and gtx as null
                17:16:11,770 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,770 TRACE [TxInterceptor] Associated gtx in txTable is null
                17:16:11,770 TRACE [TransactionTable] created new GTX: GlobalTransaction:<null>:2, local TX=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING >
                17:16:11,770 TRACE [TxInterceptor] Registering sync handler for tx TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING >, gtx GlobalTransaction:<null>:2
                17:16:11,770 TRACE [TxInterceptor] registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:2, tx=com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple@393299))
                17:16:11,770 TRACE [MVCCNodeHelper] Node / is not in context, fetching from container.
                17:16:11,770 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/}.
                17:16:11,770 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ / children=[short test]]
                17:16:11,770 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,770 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,770 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,770 TRACE [InvocationContextInterceptor] Invoked with command GetNodeCommand{fqn=/short test} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING >, globalTransaction=GlobalTransaction:<null>: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}]
                17:16:11,770 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,770 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:2
                17:16:11,770 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,770 TRACE [TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:2
                17:16:11,770 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING > is already registered.
                17:16:11,770 TRACE [MVCCNodeHelper] Node /short test is not in context, fetching from container.
                17:16:11,770 TRACE [CallInterceptor] Executing command: GetNodeCommand{fqn=/short test}.
                17:16:11,770 TRACE [GetNodeCommand] Found node, returning UnversionedNode[ /short test data=[java.lang.Object@ca88b3]]
                17:16:11,771 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,771 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,771 TRACE [ComponentRegistry] Testing if invocations are allowed.
                17:16:11,771 TRACE [InvocationContextInterceptor] Invoked with command GetKeyValueCommand{fqn=/short test, key=java.lang.Object@ca88b3, sendNodeEvent=true} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING >, globalTransaction=GlobalTransaction:<null>: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}]
                17:16:11,782 TRACE [InvocationContextInterceptor] Setting up transactional context.
                17:16:11,782 TRACE [InvocationContextInterceptor] Setting tx as TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING > and gtx as GlobalTransaction:<null>:2
                17:16:11,783 TRACE [TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
                17:16:11,783 TRACE [TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:2
                17:16:11,784 TRACE [TxInterceptor] Transaction TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:e status: ActionStatus.RUNNING > is already registered.
                17:16:11,785 TRACE [MVCCNodeHelper] Node /short test is already in context.
                17:16:11,786 TRACE [CallInterceptor] Executing command: GetKeyValueCommand{fqn=/short test, key=java.lang.Object@ca88b3, sendNodeEvent=true}.
                17:16:11,786 TRACE [GetKeyValueCommand] Found value java.lang.Object@d4a2bd
                17:16:11,786 TRACE [MVCCLockingInterceptor] Nothing to do since there is a transaction in scope.
                17:16:11,787 TRACE [InvocationContextInterceptor] Resetting invocation-scope options
                17:16:11,787 INFO [SleeTransactionManagerImpl] BIGGGGGGGGGGGGGGG ISSSSSSSSSSSSSSSSSSSSUEEEEEEEEEE
                


                • 5. Re: tx aware cache config issue
                  Manik Surtani Master

                  Is this for the first, or latest code snippet you pasted? I don't see any PUT commands in your log.

                  • 6. Re: tx aware cache config issue
                    Eduardo Martins Apprentice

                    for the latest one, isn't this the put:

                    17:16:11,769 TRACE [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{fqn=/short
                     test, dataVersion=null, globalTransaction=null, key=java.lang.Object@ca88b3, value=java.lang.Object
                    @d4a2bd} and InvocationContext [InvocationContext{transaction=TransactionImple < ac, BasicAction: -53e0fec0:ddd5:49775859:c status: ActionStatus.ABORT_ONLY >, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheM
                    odeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravita
                    tion=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal
                    =true}]
                    


                    -- Eduardo

                    • 7. Re: tx aware cache config issue
                      Manik Surtani Master

                      Ok, figured it out. It is because you are setting the tx as setRollbackOnly() before interacting with the cache. The cache sees the transaction as being invalid (since its state is not active) and does not associate any subsequent invocations with the transaction.

                      I need to check with the JTA spec and see if this is a bug or expected behaviour, although I suspect it would be a bug.

                      As a workaround, what you should do is make a cache call - even a simple one, like cache.getRoot() - before any potential rollback call.

                      Also, raise a JIRA about this and assign it to me.

                      • 8. Re: tx aware cache config issue
                        Eduardo Martins Apprentice

                        Issue created at https://jira.jboss.org/jira/browse/JBCACHE-1468

                        I'm currenlty using a workaround which consists in trapping the setRollbackOnly(), saving a flag that set rollback in transaction local data, and don't do that in the transaction manager, of course getRollabckOnly considers the flag for result, and commit will rollback if the flag is set, but I'm not sure that due to not setting it in the tx manager something bad can come in its resources.

                        By the way, is there a way to make JBoss Cache fail if no transaction exists other than add an interceptor?

                        -- Eduardo

                        • 9. Re: tx aware cache config issue
                          Manik Surtani Master

                          Thanks for creating the JIRA, I'll take a look at it.

                          "emmartins" wrote:


                          By the way, is there a way to make JBoss Cache fail if no transaction exists other than add an interceptor?



                          No, since JBC needs to work in a non-transactional way as well, i.e., when there are no ongoing transactions present.


                          • 10. Re: tx aware cache config issue
                            Manik Surtani Master

                            Did you try doing something with the cache *before* calling tm.setRollbackOnly() to see if that helped?

                            • 11. Re: tx aware cache config issue
                              Eduardo Martins Apprentice

                              I can't control the usage of setRollbackOnly(), it is exposed in JAIN SLEE applications API.

                              For now I think I will go for a solution where an interceptor makes any cache update fail if no tx is present or it is not in active or rollback state, and keep trapping the set rollback operation.

                              Another doubt, it is safe to use the same node instance in multiple transactions? I'm not doing that now but if it is safe I would consider for some nodes that are bound to factory type objects which are singleton and are made on server start.

                              • 12. Re: tx aware cache config issue
                                Manik Surtani Master

                                I have fixed the issue in trunk and will cut a 3.0.2.SP1 soon (maybe even today) so you won't need your interceptor.

                                Regarding the safety of nodes in > 1 transaction, yes it is safe since the node implementation you get is actually a delegate and there is proper context checking in place.

                                • 13. Re: tx aware cache config issue
                                  Eduardo Martins Apprentice

                                  But I still need to make it fail whenever there is no transaction, to trap possible bugs or leaks since all data storing retrieval is transaction aware :-)

                                  • 14. Re: tx aware cache config issue
                                    Manik Surtani Master

                                    If you're using maven2, grab JBC 3.0.3-SNAPSHOT and give it a go ...

                                    1 2 Previous Next