[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Galder Zamarreño updated ISPN-1258: ----------------------------------- Description: There's no guarantees at the JGroups level that in a sequence of prepare+commit calls, both will be handled by the same thread as shown in the logs: Here's a prepare call: {code}2011-07-20 21:01:44,400 2011 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-1,Infinispan-Cluster,NodeB-10116:) Attempting to execute command: PrepareCommand {gtx=GlobalTransaction:<NodeA-32281>:1:local, modifications=[PutKeyValueCommand{key=a, value=value1, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-32281>:1:local, cacheName='cache1'} [sender=NodeA-32281] ... 2011-07-20 21:01:44,404 2015 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-1,Infinispan-Cluster,NodeB- 10116:cache1) Acquired lock java.util.concurrent.locks.ReentrantLock@7cd1a1ab[Locked by thread OOB-1,Infinispan-Cluster,NodeB-10116]{code} And the commit: {code}2011-07-20 21:01:44,418 2029 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2,Infinispan-Cluster,NodeB-10116:) Attempting to execute command: CommitCommand {gtx=GlobalTransaction:<NodeA-32281>:1:local, cacheName='cache1'} [sender=NodeA-32281] ... 2011-07-20 21:01:44,423 2034 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-2,Infinispan-Cluster,NodeB- 10116:cache1) Unlock lock java.util.concurrent.locks.ReentrantLock@7cd1a1ab[Locked by thread OOB-1,Infinispan-Cluster,NodeB-10116]{code} The end result? {code} 2011-07-20 21:01:44,424 2035 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-2,Infinispan-Cluster,NodeB-10116:cache1) ISPN000136: Execution error java.lang.IllegalMonitorStateException at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:127) at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1239) at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:431) at org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer.releaseLock(AbstractPerEntryLockContainer.java:113) at org.infinispan.util.concurrent.locks.LockManagerImpl.unlock(LockManagerImpl.java:113) at org.infinispan.interceptors.LockingInterceptor.cleanupLocks(LockingInterceptor.java:375) at org.infinispan.interceptors.LockingInterceptor.visitCommitCommand(LockingInterceptor.java:98) {code} Mircea, could you have a look? was: There's no guarantees at the JGroups level that in a sequence of prepare+commit calls, both will be handled by the same thread as shown in the logs: Here's a prepare call: {code}2011-07-20 21:01:44,400 2011 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-1,Infinispan-Cluster,NodeB-10116:) Attempting to execute command: PrepareCommand {gtx=GlobalTransaction:<NodeA-32281>:1:local, modifications=[PutKeyValueCommand{key=a, value=value1, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-32281>:1:local, cacheName='cache1'} [sender=NodeA-32281] ... 2011-07-20 21:01:44,404 2015 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-1,Infinispan-Cluster,NodeB-10116:cache1) Acquired lock java.util.concurrent.locks.ReentrantLock@7cd1a1ab[Locked by thread OOB-1,Infinispan-Cluster,NodeB-10116]{code} And the commit: {code}2011-07-20 21:01:44,418 2029 TRACE [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] (OOB-2,Infinispan-Cluster,NodeB-10116:) Attempting to execute command: CommitCommand {gtx=GlobalTransaction:<NodeA-32281>:1:local, cacheName='cache1'} [sender=NodeA-32281] ... 2011-07-20 21:01:44,423 2034 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-2,Infinispan-Cluster,NodeB-10116:cache1) Unlock lock java.util.concurrent.locks.ReentrantLock@7cd1a1ab[Locked by thread OOB-1,Infinispan-Cluster,NodeB-10116]{code} The end result? {code} 2011-07-20 21:01:44,424 2035 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-2,Infinispan-Cluster,NodeB-10116:cache1) ISPN000136: Execution error java.lang.IllegalMonitorStateException at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:127) at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1239) at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:431) at org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer.releaseLock(AbstractPerEntryLockContainer.java:113) at org.infinispan.util.concurrent.locks.LockManagerImpl.unlock(LockManagerImpl.java:113) at org.infinispan.interceptors.LockingInterceptor.cleanupLocks(LockingInterceptor.java:375) at org.infinispan.interceptors.LockingInterceptor.visitCommitCommand(LockingInterceptor.java:98) {code} Mircea, could you have a look? -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Galder Zamarreño updated ISPN-1258: ----------------------------------- Attachment: IllegalMonitor_issue.patch -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Mircea Markus commented on ISPN-1258: ------------------------------------- @Manik, indeed the lock owner should not appear as the thread, but the transaction. It's odd and dangerous that this happens. I'll take a look. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Mircea Markus edited comment on ISPN-1258 at 7/28/11 5:08 PM: -------------------------------------------------------------- I've run a simple test and the lock is indeed owned by the transaction (and not the thread). I couldn't reproduce this by running the tests either, so I imagine this must be a pretty edge case. Can you provide some more context to help me reproduce this? Would be very interesting to see the logs on the transaction originator as well. {noformat}2011-07-28 20:07:50,634 TRACE [org.infinispan.commands.tx.PrepareCommand] (OOB-2,Infinispan-Cluster,NodeB-33545) Invoking remotely originated prepare: PrepareCommand {gtx=GlobalTransaction:<NodeA-48656>:1:remote, modifications=[PutKeyValueCommand{key=k, value=v, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-48656>:1:remote, cacheName='___defaultcache'} with invocation context: RemoteTxInvocationContext{flags=null} 2011-07-28 20:07:50,634 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-2,Infinispan-Cluster,NodeB-33545) Invoked with command PrepareCommand {gtx=GlobalTransaction:<NodeA-48656>:1:remote, modifications=[PutKeyValueCommand{key=k, value=v, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-48656>:1:remote, cacheName='___defaultcache'} and InvocationContext [RemoteTxInvocationContext{flags=null}] 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2,Infinispan-Cluster,NodeB-33545) Attempting to lock key=k with acquisition timeout of 10000 millis 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-2,Infinispan-Cluster,NodeB-33545) Acquired lock org.infinispan.util.concurrent.locks.OwnableReentrantLock@4e0a2a38[State = 1, empty queue][Locked by GlobalTransaction:<NodeA-48656>:1:remote] 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2,Infinispan-Cluster,NodeB-33545) Successfully acquired lock!{noformat} was (Author: mircea.markus): I've run a simple test and the lock is indeed owned by the transaction (and not the thread). I couldn't reproduce this by running the tests either, so I imagine this must be a pretty edge case. Can you provide some more context to help me reproduce this? {noformat} 2011-07-28 20:07:50,634 TRACE [org.infinispan.commands.tx.PrepareCommand] (OOB-2,Infinispan-Cluster,NodeB-33545) Invoking remotely originated prepare: PrepareCommand {gtx=GlobalTransaction:<NodeA-48656>:1:remote, modifications=[PutKeyValueCommand{key=k, value=v, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-48656>:1:remote, cacheName='___defaultcache'} with invocation context: RemoteTxInvocationContext{flags=null} 2011-07-28 20:07:50,634 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-2,Infinispan-Cluster,NodeB-33545) Invoked with command PrepareCommand {gtx=GlobalTransaction:<NodeA-48656>:1:remote, modifications=[PutKeyValueCommand{key=k, value=v, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}], onePhaseCommit=false, gtx=GlobalTransaction:<NodeA-48656>:1:remote, cacheName='___defaultcache'} and InvocationContext [RemoteTxInvocationContext{flags=null}] 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2,Infinispan-Cluster,NodeB-33545) Attempting to lock key=k with acquisition timeout of 10000 millis 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.containers.AbstractPerEntryLockContainer] (OOB-2,Infinispan-Cluster,NodeB-33545) Acquired lock org.infinispan.util.concurrent.locks.OwnableReentrantLock@4e0a2a38[State = 1, empty queue][Locked by GlobalTransaction:<NodeA-48656>:1:remote] 2011-07-28 20:07:50,634 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2,Infinispan-Cluster,NodeB-33545) Successfully acquired lock! {noformat} -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Galder Zamarreño commented on ISPN-1258: ---------------------------------------- Mircea, I can't remember how to replicate this tbh. I saw it, entered the jira, and then moved on :| -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/ISPN-1258?page=com.atlassian.jira.plugin.... ] Mircea Markus resolved ISPN-1258. --------------------------------- Resolution: Out of Date see the last comment. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira