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

[Erik Salter (JIRA)]

Erik Salter created ISPN-4840:
---------------------------------

             Summary: LockControlCommand timeouts can cause orphaned locks.
                 Key: ISPN-4840
                 URL: https://issues.jboss.org/browse/ISPN-4840
             Project: Infinispan
          Issue Type: Bug
          Components: Transactions
    Affects Versions: 7.0.0.CR1
            Reporter: Erik Salter
            Assignee: Dan Berindei


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




--
This message was sent by Atlassian JIRA
(v6.3.1#6329)