4:19 p.m.
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
5:04 p.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Brian Stansberry updated JBCACHE-923:
-------------------------------------
Summary: Acquired node lock never released after transaction timeout (was:
Aquired node lock never released after transaction timeout)
Component/s: (was: PojoCache)
Assignee: Manik Surtani (was: Ben Wang)
Priority: Major (was: Critical)
Thanks for the report. I saw your forum post earlier and had a look at the code and there
are definitely issues when more than one thread is associated with the tx.
I've removed "PojoCache" from the Component field as this is not specific to
PojoCache. And I restored the default Priority, as the priority is determined by Manik
Surtani, not by the person who reports the bug.
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
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
6:09 p.m.
New subject: [JBoss JIRA] Commented: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=comments#action_12349583 ]
Manik Surtani commented on JBCACHE-923:
---------------------------------------
Thanks for amending/reassinging, Brian.
Will have a more detailed look and discuss on the forum, but the TxInterceptor (and
supporting classes, including TransactionTable) have not been designed to cope with
multiple threads accessing the same transaction simultaneously.
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
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
2:33 a.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Jacek Halat updated JBCACHE-923:
--------------------------------
Attachment: AsyncRollbackTxTest.zip
I created and attached JUnit test to this issue.
Attached AsyncRollbackTransactionManager works like weblogic transaction manager when
transaction timeout is detected.
This test shows that if any operation on cache after tx timeout will be executed in
non-transactional context, aquired locks will be never released.
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
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 {}
--
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
7:24 p.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani updated JBCACHE-923:
----------------------------------
Fix Version/s: 2.0.0.ALPHA2
2.0.0.GA
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: 2.0.0.GA, 1.4.1.GA, 2.0.0.ALPHA2
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 {}
--
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
7:24 p.m.
New subject: [JBoss JIRA] Closed: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani closed JBCACHE-923.
---------------------------------
Resolution: Done
Fix Version/s: 1.4.1.GA
More advanced and accurate test added to CVS (branch 1.4.0) based on tests attached.
This is related to JBCACHE-785 and while the primary issue of stale thread-local variables
and locks being left over were addressed by JBCACHE-785, these tests running rollbacks on
threads different from the main transaction thread uncovered a different bug in newly
created functionality to solve JBCACHE-871.
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 {}
--
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
7:24 p.m.
New subject: [JBoss JIRA] Reopened: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani reopened JBCACHE-923:
-----------------------------------
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: 2.0.0.GA, 1.4.1.GA, 2.0.0.ALPHA2
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 {}
--
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
8:58 a.m.
New subject: [JBoss JIRA] Commented: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=comments#action_12349808 ]
Manik Surtani commented on JBCACHE-923:
---------------------------------------
Note that this failure only occured when a transaction manager attempted to roll back a
transaction using a thread different from the thread used to process the transaction. So
if your transaction manager does not do this, you'd never see this problem.
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: 2.0.0.GA, 1.4.1.GA, 2.0.0.ALPHA2
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 {}
--
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
2:28 p.m.
New subject: [JBoss JIRA] Closed: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani closed JBCACHE-923.
---------------------------------
Resolution: Done
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, 2.0.0.ALPHA2, 2.0.0.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 {}
--
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
7:39 a.m.
New subject: [JBoss JIRA] Reopened: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani reopened JBCACHE-923:
-----------------------------------
See "Scenario 4" described by Jacek in
http://jboss.org/index.html?module=bb&op=viewtopic&p=4084417#4084417
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: 2.0.0.GA, 1.4.1.GA, 2.0.0.ALPHA2
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 {}
--
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
10:40 a.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani updated JBCACHE-923:
----------------------------------
Fix Version/s: 1.4.1.SP5
2.1.0.GA
(was: 2.0.0.GA)
(was: 1.4.1.GA)
(was: 2.0.0.ALPHA2)
Affects Version/s: 1.4.1.SP4
2.0.0.GA
1.4.1.GA
Complexity: High
A new unit test to exercise this has been added. See
org.jboss.cache.transaction.SimultaneousRollbackAndPutTest
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.GA, 1.4.1.SP5
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 {}
--
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
1:43 p.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani updated JBCACHE-923:
----------------------------------
Fix Version/s: 1.4.1.SP6
(was: 1.4.1.SP5)
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.GA, 1.4.1.SP6
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 {}
--
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
9:49 a.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani updated JBCACHE-923:
----------------------------------
Fix Version/s: 1.4.1.SP7
(was: 1.4.1.SP6)
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.GA, 1.4.1.SP7
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 {}
--
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
10:28 a.m.
New subject: [JBoss JIRA] Resolved: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani resolved JBCACHE-923.
-----------------------------------
Fix Version/s: (was: 1.4.1.SP7)
Resolution: Partially Completed
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.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 {}
--
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
10:28 a.m.
New subject: [JBoss JIRA] Commented: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=comments#action_12386036 ]
Manik Surtani commented on JBCACHE-923:
---------------------------------------
So I've introduced some fixes into the pessimistic lock interceptor, to test the
validity of a transaction before acquiring locks on it, etc., which reduce the likelihood
of this race condition between a rollback thread and a worker thread.
This still isn't a 00% solution though, since it relates to some fundamental design
flaws in pessimistic locking which we hope to address with MVCC.
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.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 {}
--
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
10:28 a.m.
New subject: [JBoss JIRA] Commented: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=comments#action_12386037 ]
Manik Surtani commented on JBCACHE-923:
---------------------------------------
That should read "100% solution".
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.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 {}
--
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
4:36 a.m.
New subject: [JBoss JIRA] Updated: (JBCACHE-923) Acquired node lock never released after transaction timeout
[ http://jira.jboss.com/jira/browse/JBCACHE-923?page=all ]
Manik Surtani updated JBCACHE-923:
----------------------------------
Fix Version/s: 2.1.0.CR2
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: 2.0.0.GA, 1.4.0.SP1, 1.4.1.GA, 1.4.1.SP4
Environment: Windows XP, Weblogic 9.1
Reporter: Jacek Halat
Assigned To: Manik Surtani
Fix For: 2.1.0.GA, 2.1.0.CR2
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 {}
--
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
6258
days inactive
6580
days old
16 comments
4 participants
participants (4)
-
Brian Stansberry (JIRA) -
Jacek Halat (JIRA)
-
Manik Surtani (JIRA) -
Manik Surtani (JIRA)