[jboss-user] [JBoss Cache: Core Edition] - Re: Far cache problem (3.0.2) tx problems
rs1050
do-not-reply at jboss.com
Fri Feb 6 20:47:11 EST 2009
thank you, it did fix the exception. Here is the log with the JDBC loader, same problem as with TCPDelegatinLoader.
| 20:42:38,187 [http--8080-1$23822211] INFO TestUser:getSomething:13 - yoyo:
| 20:42:38,189 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:38,191 [http--8080-1$23822211] 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:42:38,330 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:38,330 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:38,331 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:38,332 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
| 20:42:38,344 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
| 20:42:38,345 [http--8080-1$23822211] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86
| 20:42:38,369 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 11cd8cc
| 20:42:38,371 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
| 20:42:38,372 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection at 11cd8cc
| 20:42:38,379 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:38,464 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
| 20:42:38,465 [http--8080-1$23822211] TRACE GetNodeCommand:perform:70 - Found node, returning null
| 20:42:38,466 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/user/1:86] for owner Thread[http--8080-1$23822211,5,main]
| 20:42:38,466 [http--8080-1$23822211] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86
| 20:42:38,467 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:38,475 [http--8080-1$23822211] DEBUG NearCacheImpl:getValue:42 - for fqn: /user/1:86 got this value from cache: null
| 20:42:38,476 [http--8080-1$23822211] INFO UserManagerImpl:getUser:113 - user for id: 1:86 NOT found in cache, will get from DB
| 20:42:38,483 [http--8080-1$23822211] DEBUG JtaTransactionManager:lookupTransactionManager:587 - Retrieving JTA TransactionManager from JNDI location [java:/TransactionManager]
| 20:42:38,484 [http--8080-1$23822211] DEBUG JtaTransactionManager:findUserTransaction:676 - JTA UserTransaction found at default JNDI location [java:comp/UserTransaction]
| 20:42:38,493 [http--8080-1$23822211] INFO JtaTransactionManager:checkUserTransactionAndTransactionManager:488 - Using JTA UserTransaction: UserTransactionProxy[]
| 20:42:38,494 [http--8080-1$23822211] INFO JtaTransactionManager:checkUserTransactionAndTransactionManager:499 - Using JTA TransactionManager: TransactionManagerImpl[]
| 20:42:38,496 [http--8080-1$23822211] DEBUG JtaTransactionManager:findTransactionSynchronizationRegistry:777 - JTA 1.1 [javax.transaction.TransactionSynchronizationRegistry] not available
| 20:42:38,909 [http--8080-1$23822211] INFO TestUser:getSomething:19 - updating user with good value: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:38,913 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:54 - user TX before start of TX: UserTransactionProxy[], status: 6
| 20:42:38,920 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:59 - started user TX: UserTransactionProxy[], status: 0
| 20:42:38,921 [http--8080-1$23822211] DEBUG NearCacheImpl:setValue:53 - setting value for object:/user/1:86 in cacheId:3
| 20:42:39,118 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,119 [http--8080-1$23822211] 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:42:39,128 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,129 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:f06abe25] and gtx as null
| 20:42:39,130 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$23822211,5,main]
| 20:42:39,131 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is null
| 20:42:39,147 [http--8080-1$23822211] TRACE TransactionTable:getCurrentTransaction:450 - created new GTX: GlobalTransaction:<null>:1, local TX=Transaction[01:f06abe25]
| 20:42:39,148 [http--8080-1$23822211] TRACE TxInterceptor:registerTransaction:719 - Registering sync handler for tx Transaction[01:f06abe25], gtx GlobalTransaction:<null>:1
| 20:42:39,152 [http--8080-1$23822211] TRACE TxInterceptor:registerHandler:744 - registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:1, tx=com.caucho.transaction.TransactionImpl at 13920591))
| 20:42:39,181 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,183 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:39,189 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
| 20:42:39,190 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
| 20:42:39,191 [http--8080-1$23822211] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86
| 20:42:39,215 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at b90ff7
| 20:42:39,222 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
| 20:42:39,224 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection at b90ff7
| 20:42:39,224 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:39,316 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
| 20:42:39,317 [http--8080-1$23822211] TRACE GetNodeCommand:perform:70 - Found node, returning null
| 20:42:39,317 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:39,318 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:39,318 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,329 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction:<null>:1, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}} and InvocationContext [InvocationContext{transaction=Transaction[01:f06abe25], 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}]
| 20:42:39,342 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,343 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:f06abe25] and gtx as GlobalTransaction:<null>:1
| 20:42:39,344 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$23822211,5,main]
| 20:42:39,344 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is GlobalTransaction:<null>:1
| 20:42:39,357 [http--8080-1$23822211] TRACE TxInterceptor:registerTransaction:732 - Transaction Transaction[01:f06abe25] is already registered.
| 20:42:39,358 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:39,359 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:417 - Node [/user/1:86] is null in memory. Must load? true
| 20:42:39,359 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=true
| 20:42:39,372 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadData:494 - Attempting to load data for /user/1:86
| 20:42:39,394 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 5db8ff
| 20:42:39,395 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT node FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
| 20:42:39,397 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:close:176 - closed non tx connection: com.mysql.jdbc.JDBC4Connection at 5db8ff
| 20:42:39,397 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadData:497 - Node /user/1:86 exists? false
| 20:42:39,494 [http--8080-1$23822211] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user
| 20:42:39,495 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,497 [http--8080-1$23822211] TRACE MVCCNodeFactory:createChildNode:140 - Created new child with fqn [/user]
| 20:42:39,501 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,504 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,511 [http--8080-1$23822211] TRACE MVCCNodeFactory:createChildNode:140 - Created new child with fqn [/user/1:86]
| 20:42:39,512 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,513 [http--8080-1$23822211] TRACE PutKeyValueCommand:perform:76 - Perform('GlobalTransaction:<null>:1', '/user/1:86', k='d', v='TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}')
| 20:42:39,524 [http--8080-1$23822211] 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:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,525 [http--8080-1$23822211] TRACE PutKeyValueCommand:perform:88 - Old value is null, dataLoaded=false
| 20:42:39,532 [http--8080-1$23822211] 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='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:f06abe25], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:39,540 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:39,541 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:39,557 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:87 - committing tx
| 20:42:39,558 [http--8080-1$23822211] TRACE TxInterceptor:beforeCompletion:865 - Running beforeCompletion on gtx GlobalTransaction:<null>:1
| 20:42:39,559 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,559 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:f06abe25] and gtx as GlobalTransaction:<null>:1
| 20:42:39,563 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,563 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,564 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:f06abe25] and gtx as GlobalTransaction:<null>:1
| 20:42:39,565 [http--8080-1$23822211] TRACE CacheStoreInterceptor:handlePrepareCommand:195 - transactional so don't put stuff in the cloader yet.
| 20:42:39,577 [http--8080-1$23822211] TRACE CacheStoreInterceptor:prepareCacheLoader:331 - Cache loader modification list: [PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction:<null>:1, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}]
| 20:42:39,581 [http--8080-1$23822211] TRACE CacheStoreInterceptor:prepareCacheLoader:339 - Converted method calls to cache loader modifications. List size: 1
| 20:42:39,610 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,611 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:prepare:83 - opened tx connection: tx=GlobalTransaction:<null>:1, con=com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,613 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,614 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT node FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
| 20:42:39,705 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,706 [http--8080-1$23822211] 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:42:39,707 [http--8080-1$23822211] TRACE CacheMarshaller300:objectToObjectStream:173 - Marshalling object {d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}
| 20:42:39,720 [http--8080-1$23822211] TRACE CacheMarshaller300:marshallObject:446 - Warning: using object serialization for class com.threadmap.site.user.impl.TMUserImpl
| 20:42:39,726 [http--8080-1$23822211] TRACE CacheMarshaller300:objectToObjectStream:204 - Done serializing object: {d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}
| 20:42:39,730 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,732 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/user]
| 20:42:39,734 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,735 [http--8080-1$23822211] 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:42:39,748 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,749 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT '1' FROM jbosscache WHERE fqn = ?] with params [/]
| 20:42:39,751 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:39,753 [http--8080-1$23822211] 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:42:39,762 [http--8080-1$23822211] TRACE CallInterceptor:visitPrepareCommand:70 - Suppressing invocation of method handlePrepareCommand.
| 20:42:39,763 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:39,768 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,769 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:39,778 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,779 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[] and gtx as GlobalTransaction:<null>:1
| 20:42:39,780 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,780 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:917 - calling aftercompletion for GlobalTransaction:<null>:1
| 20:42:39,792 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:932 - Running commit phase. One phase? false
| 20:42:39,793 [http--8080-1$23822211] TRACE TxInterceptor:runCommitPhase:549 - Running commit for GlobalTransaction:<null>:1
| 20:42:39,794 [http--8080-1$23822211] TRACE CallInterceptor:visitCommitCommand:84 - Suppressing invocation of method handleCommitCommand.
| 20:42:39,795 [http--8080-1$23822211] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/user]. deleted=false valid=true changed=true created=true
| 20:42:39,807 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/user] for owner GlobalTransaction:<null>:1
| 20:42:39,808 [http--8080-1$23822211] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user
| 20:42:39,808 [http--8080-1$23822211] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/user/1:86]. deleted=false valid=true changed=true created=true
| 20:42:39,809 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/user/1:86] for owner GlobalTransaction:<null>:1
| 20:42:39,818 [http--8080-1$23822211] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86
| 20:42:39,820 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:39,823 [http--8080-1$23822211] 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=true, newView=null, buddyGroup=null}
| 20:42:39,834 [http--8080-1$23822211] TRACE TxInterceptor:handleCommitRollback:527 - Finished local commit/rollback method for GlobalTransaction:<null>:1
| 20:42:39,841 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:934 - Finished commit phase
| 20:42:39,842 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,842 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:39,843 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:99 - User TX: UserTransactionProxy[], status: 6
| 20:42:39,849 [http--8080-1$23822211] INFO TestUser:getSomething:22 - get user again
| 20:42:39,850 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,850 [http--8080-1$23822211] 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:42:39,862 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,863 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:39,863 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:39,864 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:438 - Don't load [/user/1:86], key requested is null
| 20:42:39,876 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:39,876 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:39,877 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
| 20:42:39,879 [http--8080-1$23822211] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /user/1:86 data=[d]]}
| 20:42:39,890 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
| 20:42:39,891 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:39,892 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,898 [http--8080-1$23822211] 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:42:39,906 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,907 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:39,908 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:39,911 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:443 - Don't load [/user/1:86], already have necessary key in memory
| 20:42:39,924 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:39,925 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:39,926 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetKeyValueCommand{fqn=/user/1:86, key=d, sendNodeEvent=true}.
| 20:42:39,926 [http--8080-1$23822211] TRACE GetKeyValueCommand:perform:89 - Found value TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:39,935 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
| 20:42:39,936 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:39,936 [http--8080-1$23822211] DEBUG NearCacheImpl:getValue:42 - for fqn: /user/1:86 got this value from cache: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:39,949 [http--8080-1$23822211] INFO UserManagerImpl:getUser:111 - user for id: 1:86 was found in cache: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:39,950 [http--8080-1$23822211] INFO TestUser:getSomething:24 - user before bad value: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:39,951 [http--8080-1$23822211] INFO TestUser:getSomething:31 - before update : TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:39,962 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:54 - user TX before start of TX: UserTransactionProxy[], status: 6
| 20:42:39,963 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:59 - started user TX: UserTransactionProxy[], status: 0
| 20:42:39,963 [http--8080-1$23822211] DEBUG NearCacheImpl:setValue:53 - setting value for object:/user/1:86 in cacheId:3
| 20:42:39,964 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:39,968 [http--8080-1$23822211] 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:42:39,979 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:39,980 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:a0d7f853] and gtx as null
| 20:42:39,981 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$23822211,5,main]
| 20:42:39,981 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is null
| 20:42:39,999 [http--8080-1$23822211] TRACE TransactionTable:getCurrentTransaction:450 - created new GTX: GlobalTransaction:<null>:2, local TX=Transaction[01:a0d7f853]
| 20:42:40,000 [http--8080-1$23822211] TRACE TxInterceptor:registerTransaction:719 - Registering sync handler for tx Transaction[01:a0d7f853], gtx GlobalTransaction:<null>:2
| 20:42:40,001 [http--8080-1$23822211] TRACE TxInterceptor:registerHandler:744 - registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:2, tx=com.caucho.transaction.TransactionImpl at 13920591))
| 20:42:40,013 [http--8080-1$23822211] 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:a0d7f853], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:40,014 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:40,027 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:438 - Don't load [/user/1:86], key requested is null
| 20:42:40,028 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:40,029 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:40,030 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
| 20:42:40,031 [http--8080-1$23822211] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /user/1:86 data=[d]]}
| 20:42:40,040 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:40,041 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:40,045 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:40,046 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction:<null>:2, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}} and InvocationContext [InvocationContext{transaction=Transaction[01:a0d7f853], 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}]
| 20:42:40,056 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,057 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:a0d7f853] and gtx as GlobalTransaction:<null>:2
| 20:42:40,058 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:446 - local transaction exists - registering global tx if not present for Thread[http--8080-1$23822211,5,main]
| 20:42:40,058 [http--8080-1$23822211] TRACE TxInterceptor:attachGlobalTransaction:451 - Associated gtx in txTable is GlobalTransaction:<null>:2
| 20:42:40,073 [http--8080-1$23822211] TRACE TxInterceptor:registerTransaction:732 - Transaction Transaction[01:a0d7f853] is already registered.
| 20:42:40,075 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:40,076 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:443 - Don't load [/user/1:86], already have necessary key in memory
| 20:42:40,077 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:40,093 [http--8080-1$23822211] TRACE MVCCLockManager:lockAndRecord:126 - Attempting to lock /user/1:86
| 20:42:40,094 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForWriting:208 - Retrieving wrapped node /user/1:86
| 20:42:40,095 [http--8080-1$23822211] TRACE PutKeyValueCommand:perform:76 - Perform('GlobalTransaction:<null>:2', '/user/1:86', k='d', v='TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}')
| 20:42:40,106 [http--8080-1$23822211] 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='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:a0d7f853], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:40,116 [http--8080-1$23822211] TRACE PutKeyValueCommand:perform:88 - Old value is TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}, dataLoaded=false
| 20:42:40,117 [http--8080-1$23822211] 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='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}, fqn=/user/1:86, transaction=Transaction[01:a0d7f853], originLocal=true, targetFqn=null, successful=false, newView=null, buddyGroup=null}
| 20:42:40,127 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:40,132 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:40,165 [http--8080-1$23822211] INFO XmlBeanDefinitionReader:loadBeanDefinitions:323 - Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
| 20:42:40,186 [http--8080-1$23822211] INFO SQLErrorCodesFactory:<init>:128 - SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase]
| 20:42:40,192 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:91 - rolling back tx
| 20:42:40,192 [http--8080-1$23822211] TRACE TxInterceptor:beforeCompletion:865 - Running beforeCompletion on gtx GlobalTransaction:<null>:2
| 20:42:40,252 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,253 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:a0d7f853] and gtx as GlobalTransaction:<null>:2
| 20:42:40,253 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:40,254 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,261 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[01:a0d7f853] and gtx as GlobalTransaction:<null>:2
| 20:42:40,262 [http--8080-1$23822211] TRACE CacheStoreInterceptor:handlePrepareCommand:195 - transactional so don't put stuff in the cloader yet.
| 20:42:40,262 [http--8080-1$23822211] TRACE CacheStoreInterceptor:prepareCacheLoader:331 - Cache loader modification list: [PutKeyValueCommand{fqn=/user/1:86, dataVersion=null, globalTransaction=GlobalTransaction:<null>:2, key=d, value=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}]
| 20:42:40,275 [http--8080-1$23822211] TRACE CacheStoreInterceptor:prepareCacheLoader:339 - Converted method calls to cache loader modifications. List size: 1
| 20:42:40,276 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:40,277 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:prepare:83 - opened tx connection: tx=GlobalTransaction:<null>:2, con=com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:40,277 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:40,290 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [SELECT node FROM jbosscache WHERE fqn = ?] with params [/user/1:86]
| 20:42:40,297 [http--8080-1$23822211] TRACE CacheMarshaller300:objectFromObjectStream:166 - Unmarshalled object {d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='1233970958909', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}
| 20:42:40,298 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection at 175650e
| 20:42:40,304 [http--8080-1$23822211] TRACE JDBCCacheLoader:prepareAndLogStatement:116 - Executing SQL statement [UPDATE jbosscache SET node = ? WHERE fqn = ?]
| 20:42:40,305 [http--8080-1$23822211] TRACE CacheMarshaller300:objectToObjectStream:173 - Marshalling object {d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}
| 20:42:40,317 [http--8080-1$23822211] TRACE CacheMarshaller300:marshallObject:446 - Warning: using object serialization for class com.threadmap.site.user.impl.TMUserImpl
| 20:42:40,318 [http--8080-1$23822211] TRACE CacheMarshaller300:objectToObjectStream:204 - Done serializing object: {d=TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}}
| 20:42:40,331 [http--8080-1$23822211] TRACE CallInterceptor:visitPrepareCommand:70 - Suppressing invocation of method handlePrepareCommand.
| 20:42:40,332 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:40,333 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,333 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:40,344 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,350 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as Transaction[] and gtx as GlobalTransaction:<null>:2
| 20:42:40,351 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:40,351 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:917 - calling aftercompletion for GlobalTransaction:<null>:2
| 20:42:40,358 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:940 - Running rollback phase
| 20:42:40,359 [http--8080-1$23822211] TRACE TxInterceptor:runRollbackPhase:596 - running rollback for GlobalTransaction:<null>:2
| 20:42:40,360 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:visitRollbackCommand:218 - Removing temporarily created nodes
| 20:42:40,360 [http--8080-1$23822211] TRACE CallInterceptor:visitRollbackCommand:91 - Suppressing invocation of method handleRollbackCommand.
| 20:42:40,361 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:cleanupLocks:387 - Releasing lock on [/user/1:86] for owner GlobalTransaction:<null>:2
| 20:42:40,369 [http--8080-1$23822211] TRACE MVCCLockManager:unlock:140 - Attempting to unlock /user/1:86
| 20:42:40,370 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:355 - Nothing to do since there is a transaction in scope.
| 20:42:40,371 [http--8080-1$23822211] 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:42:40,385 [http--8080-1$23822211] TRACE TxInterceptor:handleCommitRollback:527 - Finished local commit/rollback method for GlobalTransaction:<null>:2
| 20:42:40,386 [http--8080-1$23822211] TRACE TxInterceptor:afterCompletion:942 - Finished rollback phase
| 20:42:40,387 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:40,388 [http--8080-1$23822211] TRACE TxInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:40,389 [http--8080-1$23822211] INFO UserManagerImpl:updateUser:99 - User TX: UserTransactionProxy[], status: 6
| 20:42:41,400 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:41,400 [http--8080-1$23822211] 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:42:41,415 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:41,418 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:41,418 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:41,419 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:438 - Don't load [/user/1:86], key requested is null
| 20:42:41,427 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:41,429 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:41,429 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/user/1:86}.
| 20:42:41,430 [http--8080-1$23822211] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /user/1:86 data=[d]]}
| 20:42:41,443 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
| 20:42:41,444 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:41,445 [http--8080-1$23822211] TRACE ComponentRegistry:invocationsAllowed:877 - Testing if invocations are allowed.
| 20:42:41,446 [http--8080-1$23822211] 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:42:41,457 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
| 20:42:41,459 [http--8080-1$23822211] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
| 20:42:41,459 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /user/1:86 is not in context, fetching from container.
| 20:42:41,460 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:mustLoad:443 - Don't load [/user/1:86], already have necessary key in memory
| 20:42:41,477 [http--8080-1$23822211] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /user/1:86 mustLoad=false
| 20:42:41,478 [http--8080-1$23822211] TRACE MVCCNodeHelper:wrapNodeForReading:145 - Node /user/1:86 is already in context.
| 20:42:41,479 [http--8080-1$23822211] TRACE CallInterceptor:handleDefault:98 - Executing command: GetKeyValueCommand{fqn=/user/1:86, key=d, sendNodeEvent=true}.
| 20:42:41,484 [http--8080-1$23822211] TRACE GetKeyValueCommand:perform:89 - Found value TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:41,498 [http--8080-1$23822211] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
| 20:42:41,499 [http--8080-1$23822211] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
| 20:42:41,499 [http--8080-1$23822211] DEBUG NearCacheImpl:getValue:42 - for fqn: /user/1:86 got this value from cache: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:41,513 [http--8080-1$23822211] INFO UserManagerImpl:getUser:111 - user for id: 1:86 was found in cache: TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
| 20:42:41,515 [http--8080-1$23822211] INFO TestUser:getSomething:45 - after update : TMUserImpl{_id=1:86, _username='asdf', _SLUsername='asdf', _password='{salt}', _email='asdf at xomc.om233', _userStateCd=A}
|
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4207894#4207894
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4207894
More information about the jboss-user
mailing list