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

RH Bugzilla Integration (JIRA) issues at jboss.org
Wed Nov 5 21:25:36 EST 2014 

    [ https://issues.jboss.org/browse/ISPN-4840?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13017665#comment-13017665 ] 

RH Bugzilla Integration commented on ISPN-4840:
-----------------------------------------------

Dave Stahl <dstahl at redhat.com> changed the Status of [bug 1160638|https://bugzilla.redhat.com/show_bug.cgi?id=1160638] from MODIFIED to ON_QA

> 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



--
This message was sent by Atlassian JIRA
(v6.3.8#6338)

More information about the infinispan-issues mailing list