[jboss-jira] [JBoss JIRA] Created: (JBCACHE-923) Aquired node lock never released after transaction timeout

[Jacek Halat (JIRA)]

Aquired node lock never released after transaction timeout
----------------------------------------------------------

                 Key: JBCACHE-923
                 URL: http://jira.jboss.com/jira/browse/JBCACHE-923
             Project: JBoss Cache
          Issue Type: Bug
      Security Level: Public (Everyone can see)
          Components: PojoCache
    Affects Versions: 1.4.0.SP1
         Environment: Windows XP, Weblogic 9.1
            Reporter: Jacek Halat
         Assigned To: Ben Wang
            Priority: Critical


Under weblogic 9.1 (and probably earlier version too, not tested) in some situations locks aquired on nodes are never released. Only way to release locks is stop and start again treecache.
On WebLogic the rollback after a tx timeout is handled in a separate thread (and all registered transaction synchronization handlers are invoked in separated thread! In treecache information about InvocationContext (GlobalTransaction, Transaction etc) is stored in ThreadLocal. In this situation SynchronizationHandler is scrubbing NOT correct invocationContext with information about currend rolled-back transaction, but new created empty invocationContext !!!! Informations from TransactionTable are correctly removed, because mapping of transactions is not stored in ThreadLocal variable.

This caused unexpected effects:
Information about GlobalTransaction is not cleared and when in main thread TransactionTimedOutException is catched and put/get operations without explicity created transaction are invoked, TreeCache is trying aquire RL/WL on node and caller is set to non-exist and cleared GlobalTransaction. Lock is aquired but not added to LockTable! (and not released).
>From now every access to locked node failed, because RL/WL can't be aquired in 10 secs. Only way to get system working is stop and start again TreeCache.

2007-01-04 10:13:42,092 DEBUG  - calling aftercompletion for GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:13:42,092 DEBUG  - Running rollback phase
2007-01-04 10:13:42,092 DEBUG  -  running rollback for GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:13:42,092 DEBUG  - PessimisticLockInterceptor invoked for method rollback(GlobalTransaction:<192.168.141.1:2100>:1)
2007-01-04 10:13:42,092 DEBUG  - called to rollback cache with GlobalTransaction=GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:13:42,092 DEBUG  - _remove(GlobalTransaction:<192.168.141.1:2100>:1, "/NODEA/NODEB", systemProperty)
2007-01-04 10:13:42,092 DEBUG  - _remove(GlobalTransaction:<192.168.141.1:2100>:1, "/NODEA/NODEB")
2007-01-04 10:13:42,092 DEBUG  - removed child NODEB
2007-01-04 10:13:42,092 DEBUG  - releasing lock for /NODEA/NODEB (<unlocked>)
2007-01-04 10:13:42,092 DEBUG  - releasing lock for /NODEA (read owners=[GlobalTransaction:<192.168.141.1:2100>:1])
2007-01-04 10:13:42,092 DEBUG  - removing local transaction Name=FooManager.foo,Xid=BEA1-00068143BD8A02E8BAA1(4771853),Status=Rolled back. [Reason=weblogic.transaction.internal.TimedOutException: Transaction timed out after 20 seconds 
BEA1-00068143BD8A02E8BAA1],numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=30,seconds left=20,activeThread=Thread[Timer-5,5,Pooled Threads],XAServerResourceInfo[dataSource]=(ServerResourceInfo[dataSource]=(state=rolledback,assigned=AdminServer),xar=dataSource,re-Registered = false),SCInfo[sample_domain+AdminServer]=(state=rolledback),properties=({weblogic.transaction.name=FooManager.foo}),local properties=({weblogic.jdbc.jta.dataSource=[ No XAConnection is attached to this TxInfo ]}),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=AdminServer+10.1.1.218:9002+sample_domain+admin+, XAResources={dataSource, WLStore_sample_domain__WLS_AdminServer},NonXAResources={})],CoordinatorURL=AdminServer+10.1.1.218:9002+sample_domain+admin+) and global transaction GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:13:42,092 DEBUG  - bypassed locking as method rollback() doesn't require locking
2007-01-04 10:13:42,092 DEBUG  - Suppressing invocation of method rollback(GlobalTransaction:<192.168.141.1:2100>:1) on cache.
2007-01-04 10:13:42,092 DEBUG  - Attempting to release locks on current thread.  Lock table is {}
2007-01-04 10:13:42,092 DEBUG  - Finished local commit/rollback method for GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:13:42,092 DEBUG  - Finished rollback phase
(...)
2007-01-04 10:14:12,302 DEBUG  - Non-tx and non crud meth
2007-01-04 10:14:37,310 DEBUG  - (192.168.141.1:2100) call on method [_get(/NODEC, NODE_VALUE, true)]
2007-01-04 10:14:37,310 DEBUG  - PessimisticLockInterceptor invoked for method _get(/NODEC, NODE_VALUE, true)
2007-01-04 10:14:37,310 DEBUG  - Attempting to lock node /NODEC for owner GlobalTransaction:<192.168.141.1:2100>:1
2007-01-04 10:14:37,310 DEBUG  - acquiring RL: fqn=/NODEC, caller=GlobalTransaction:<192.168.141.1:2100>:1, lock=<unlocked>
2007-01-04 10:14:37,310 DEBUG  - acquired RL: fqn=/NODEC, caller=GlobalTransaction:<192.168.141.1:2100>:1, lock=read owners=[GlobalTransaction:<192.168.141.1:2100>:1]
2007-01-04 10:14:37,310 ERROR  - transaction entry not found for (gtx=GlobalTransaction:<192.168.141.1:2100>:1)
2007-01-04 10:14:37,310 DEBUG  - Invoking method _get(/NODEC, NODE_VALUE, true) on cache.
2007-01-04 10:14:37,310 DEBUG  - _get("/NODEC", NODE_VALUE, "true")
2007-01-04 10:14:37,310 DEBUG  - Attempting to release locks on current thread.  Lock table is {} 

	

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira