-
-
16. Re: Far cache problem (3.0.2) tx problems
Could you please paste your full cfg file? Something seems amiss. I don't even see any marshaller stream versioning info in your logs.
-
17. Re: Far cache problem (3.0.2) tx problems
Here is the full config. Commented out section is what i used for TcpDelegatingCacheLoader.
<?xml version="1.0" encoding="UTF-8"?> <jbosscache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="urn:jboss:jbosscache-core:config:3.0"> <locking isolationLevel="READ_COMMITTED" lockParentForChildInsertRemove="false" lockAcquisitionTimeout="20000" nodeLockingScheme="mvcc" writeSkewCheck="false" concurrencyLevel="500"/> <transaction transactionManagerLookupClass="org.jboss.cache.transaction.GenericTransactionManagerLookup" syncRollbackPhase="false" syncCommitPhase="false"/> <jmxStatistics enabled="false"/> <shutdown hookBehavior="DEFAULT"/> <listeners asyncPoolSize="1" asyncQueueSize="1000000"/> <invocationBatching enabled="false"/> <serialization objectInputStreamPoolSize="12" objectOutputStreamPoolSize="14" version="3.0.0" marshallerClass="org.jboss.cache.marshall.VersionAwareMarshaller" useLazyDeserialization="false" useRegionBasedMarshalling="false"/> <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="false" 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=xxx cache.jdbc.user=xxx cache.jdbc.password=xxx </properties> </loader> </loaders> </jbosscache>
Thank you. -
18. Re: Far cache problem (3.0.2) tx problems
I see your problem - don't specify VersionAwareMarshaller in your marshallerClass attrib of the serialization attrib. This should be the underlying marshaller like CacheMarshaller300.
TBH, you could just leave this blank. It is only really meant for communication between different JBC versions. -
19. Re: Far cache problem (3.0.2) tx problems
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@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@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@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@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@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@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@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@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@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@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@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@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@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@175650e 20:42:39,613 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@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@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@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@xomc.om233', _userStateCd=A}} 20:42:39,730 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@175650e 20:42:40,277 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@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@xomc.om233', _userStateCd=A}} 20:42:40,298 [http--8080-1$23822211] TRACE NonManagedConnectionFactory:getConnection:107 - using connection: com.mysql.jdbc.JDBC4Connection@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@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@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@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@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@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@xomc.om233', _userStateCd=A}