[infinispan-issues] [JBoss JIRA] (ISPN-4840) LockControlCommand timeouts can cause orphaned locks

LockControlCommand timeouts can cause orphaned locks ---------------------------------------------------- Key: ISPN-4840 URL: https://issues.jboss.org/browse/ISPN-4840 Project: Infinispan Issue Type: Bug Components: Core, Transactions Affects Versions: 7.0.0.CR1 Reporter: Erik Salter Assignee: Dan Berindei Fix For: 7.0.0.Final If an originator times out on sending a pessimistic LockControlCommand, the receiver may still get the message. In this case, the originator will send a TxCompletionCommand. Because of this, the receiver will remove the registered remote transaction from its transaction table. If, however, another thread is processing the remote LCC command, it could acquire the lock(s) after the referencing remoteTx is removed. Thus, the affected keys will remain locked indefinitely. A simple solution would be to add a check to see if there's a remote transaction when the LCC thread verifies the remote transaction. This would be in addition to checking if the transaction is completed. See the following TRACE messages: -- Local TX created 2014-10-10 11:27:28,899 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local, topologyId=64, age(ms)=0 -- Remote TX created 2014-10-10 11:27:28,525 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Created and registered remote transaction RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=0 -- Originator times out on LCC 2014-10-10 11:27:36,902 WARN [org.infinispan.remoting.rpc.RpcManagerImpl] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) ISPN000071: Caught exception when handling command LockControlCommand{cache=eigAllocation, keys=[EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130]], flags=null, unlock=false} org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL) at org.infinispan.util.Util.rewrapAsCacheException(Util.java:542) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:188) ... at org.infinispan.interceptors.distribution.TxDistributionInterceptor.visitLockControlCommand(TxDistributionInterceptor.java:204) at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134) at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177) at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120) at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:235) at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134) at org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177) at org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:116) ... at org.infinispan.CacheImpl.lock(CacheImpl.java:565) at org.infinispan.CacheImpl.lock(CacheImpl.java:548) ... Caused by: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL) at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:390) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:303) at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:181) ... 91 more 2014-10-10 11:27:36,936 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false 2014-10-10 11:27:36,937 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) ISPN000136: Execution error org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to 240-west-dht2.comcast.net-30190(CH2-Chicago-IL) at org.infinispan.util.Util.rewrapAsCacheException(Util.java:542) ... -- Same stack trace -- Remote TX removed -- must be from TxCompletionMessage since isMarkedForRollback == false 2014-10-10 11:27:36,530 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2963,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Removed remote transaction GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local ? RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=8004 2014-10-10 11:27:36,530 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2963,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Removed RemoteTransaction{modifications=[], lookedUpEntries={}, lockedKeys=null, backupKeyLocks=null, missingLookedUpEntries=false, isMarkedForRollback=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, topologyId=63, age(ms)=8004 from transaction table. -- Local TX removed 2014-10-10 11:27:36,937 TRACE [org.infinispan.transaction.TransactionTable] (OOB-1353,session-resource-cluster,240-east-dht2.comcast.net-46326(CMC-Denver-CO)) Removed LocalTransaction{remoteLockedNodes=[240-east-dht2.comcast.net-46326(CMC-Denver-CO), 240-west-dht2.comcast.net-30190(CH2-Chicago-IL)], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, isFromStateTransfer=false} globalTx=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:local, topologyId=64, age(ms)=8038 from transaction table. -- Lock acquisition completes! 2014-10-10 11:27:39,195 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Attempting to lock EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130] with acquisition timeout of 5000 millis 2014-10-10 11:27:39,198 TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Successfully acquired lock EdgeResourceCacheKey[edgeDeviceId=2878,resourceId=11130]! 2014-10-10 11:27:39,202 TRACE [org.infinispan.transaction.TransactionTable] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) Transaction=GlobalTransaction:<240-east-dht2.comcast.net-46326(CMC-Denver-CO)>:859804:remote, nodeMaxPrunedTxId=858439 -- Not in completion map since transaction was removed without commit or rollback. Lock never releases 2014-10-10 11:27:39,203 TRACE [org.infinispan.interceptors.TxInterceptor] (OOB-2850,session-resource-cluster,240-west-dht2.comcast.net-30190(CH2-Chicago-IL)) invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false