-
1. Re: tx aware cache config issue
manik Jan 21, 2009 4:06 AM (in response to emmartins)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
emmartins Jan 21, 2009 8:57 AM (in response to emmartins)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 Jan 21, 2009 10:30 AM (in response to emmartins)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
emmartins Jan 21, 2009 12:20 PM (in response to emmartins)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 Jan 21, 2009 2:13 PM (in response to emmartins)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
emmartins Jan 21, 2009 4:01 PM (in response to emmartins)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 Jan 22, 2009 11:35 AM (in response to emmartins)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
emmartins Jan 22, 2009 3:08 PM (in response to emmartins)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 Jan 23, 2009 3:49 AM (in response to emmartins)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 Jan 23, 2009 6:03 AM (in response to emmartins)Did you try doing something with the cache *before* calling tm.setRollbackOnly() to see if that helped?
-
11. Re: tx aware cache config issue
emmartins Jan 23, 2009 8:19 AM (in response to emmartins)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 Jan 23, 2009 8:36 AM (in response to emmartins)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
emmartins Jan 23, 2009 1:26 PM (in response to emmartins)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 Jan 23, 2009 1:40 PM (in response to emmartins)If you're using maven2, grab JBC 3.0.3-SNAPSHOT and give it a go ...