-
1. Re: Far cache problem (3.0.2) tx problems
manik Jan 31, 2009 4:52 AM (in response to rs1050)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 Jan 31, 2009 3:17 PM (in response to 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 Feb 2, 2009 8:23 AM (in response to rs1050)Could you please enable JBoss Cache TRACE level logging?
-
4. Re: Far cache problem (3.0.2) tx problems
rs1050 Feb 2, 2009 8:29 PM (in response to 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 Feb 3, 2009 4:30 AM (in response to rs1050)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 Feb 3, 2009 9:10 PM (in response to 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 Feb 4, 2009 6:40 AM (in response to rs1050)Could you please paste the full loaders config element, using the code button?
-
8. Re: Far cache problem (3.0.2) tx problems
rs1050 Feb 4, 2009 7:08 AM (in response to 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 Feb 4, 2009 7:14 AM (in response to rs1050)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 Feb 4, 2009 7:20 AM (in response to rs1050)still getting same exception, same line on VersionAwareMarshaller (334)
-
11. Re: Far cache problem (3.0.2) tx problems
rs1050 Feb 4, 2009 10:29 AM (in response to rs1050)still getting same exception, same line on VersionAwareMarshaller (334)
-
12. Re: Far cache problem (3.0.2) tx problems
rs1050 Feb 4, 2009 10:31 AM (in response to rs1050)sorry for posting twice, i thought the first post got lost
-
13. Re: Far cache problem (3.0.2) tx problems
rs1050 Feb 5, 2009 3:30 PM (in response to 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 Feb 5, 2009 3:47 PM (in response to rs1050)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?