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

Acquired 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) Affects Versions: 1.4.0.SP1 Environment: Windows XP, Weblogic 9.1 Reporter: Jacek Halat Assigned To: Manik Surtani Fix For: 1.4.1.GA Attachments: AsyncRollbackTxTest.zip 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 {}