Bug 901162 (JBPAPP6-1275) - [GSS](6.4.z) TimeoutException: Unable to acquire lock
Summary: [GSS](6.4.z) TimeoutException: Unable to acquire lock
Keywords:
Status: CLOSED WONTFIX
Alias: JBPAPP6-1275
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: Clustering
Version: 6.1.1,6.2.0,6.3.0
Hardware: Unspecified
OS: Unspecified
urgent
high
Target Milestone: GA
: ---
Assignee: Paul Ferraro
QA Contact: Ladislav Thon
Russell Dickenson
URL: http://jira.jboss.org/jira/browse/JBP...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-11-05 13:27 UTC by Jitka Kozana
Modified: 2018-12-05 15:46 UTC (History)
16 users (show)

Fixed In Version:
Doc Type: Known Issue
Doc Text:
A Known Issue exists in this release of JBoss EAP 6 that produces a `TimeoutException: Unable to acquire lock` under some circumstances. This issue is expected to be resolved in a later release.
Clone Of:
Environment:
Last Closed: 2016-11-25 16:36:51 UTC
Type: Bug

Attachments (Terms of Use)
Add an attachment (proposed patch, testcase, etc.)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker JBPAPP6-1275 0 Major Closed TimeoutException: Unable to acquire lock 2018-11-12 16:21:42 UTC

Description Jitka Kozana 2012-11-05 13:27:05 UTC 
project_key: JBPAPP6

{code}
[JBossINF] 09:11:50,929 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (Incoming-11,null) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [{[-124, 67, 80, -33, 101, -86, 71, -103, -85, -21, -34, 111, -56, 57, -64, -73]}] for requestor [GlobalTransaction:<perf19/ejb>:257937:remote]! Lock held by [GlobalTransaction:<perf18/ejb>:138097:local]
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:216)
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:189)
[JBossINF] 	at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:179)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:209)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:136)
[JBossINF] 	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:242)
[JBossINF] 	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
[JBossINF] 	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:324)
[JBossINF] 	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:119)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:58)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:106)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:213)
[JBossINF] 	at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:85)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:132)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:91)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:70)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:133)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345)
[JBossINF] 	at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:128)
[JBossINF] 	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:127)
[JBossINF] 	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:136)
[JBossINF] 	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithRetry(InboundInvocationHandlerImpl.java:162)
[JBossINF] 	at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:114)
[JBossINF] 	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:226)
[JBossINF] 	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:203)
[JBossINF] 	at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:459)
[JBossINF] 	at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:366)
[JBossINF] 	at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
[JBossINF] 	at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:602)
[JBossINF] 	at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
[JBossINF] 	at org.jgroups.JChannel.up(JChannel.java:716)
[JBossINF] 	at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
[JBossINF] 	at org.jgroups.protocols.RSVP.up(RSVP.java:188)
[JBossINF] 	at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
[JBossINF] 	at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
[JBossINF] 	at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
[JBossINF] 	at org.jgroups.protocols.pbcast.GMS.up(GMS.java:889)
[JBossINF] 	at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
[JBossINF] 	at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:793)
[JBossINF] 	at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:365)
[JBossINF] 	at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:602)
[JBossINF] 	at org.jgroups.protocols.BARRIER.up(BARRIER.java:102)
[JBossINF] 	at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
[JBossINF] 	at org.jgroups.protocols.FD.up(FD.java:273)
[JBossINF] 	at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
[JBossINF] 	at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
[JBossINF] 	at org.jgroups.protocols.Discovery.up(Discovery.java:359)
[JBossINF] 	at org.jgroups.stack.Protocol.up(Protocol.java:363)
[JBossINF] 	at org.jgroups.protocols.TP.passMessageUp(TP.java:1185)
[JBossINF] 	at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1733)
[JBossINF] 	at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1715)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_30]
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_30]
[JBossINF] 	at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30]
{code}
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EAP6/view/EAP6-Failover/job/eap-6x-failover-ejb-ejbservlet-netDown-dist-async/4/artifact/report/config/jboss-perf18/server.log
Comment 1 Jitka Kozana 2012-11-05 14:36:50 UTC 
Seen also here:
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EAP6/view/EAP6-Failover/job/eap-6x-failover-http-session-netDown-repl-async/2/artifact/report/config/jboss-perf18/server.log
(just slightly more readable server.log, imo).
Comment 2 Anne-Louise Tangring 2012-11-13 20:53:13 UTC 
Docs QE Status: Removed: NEW
Comment 3 Ladislav Thon 2013-03-11 10:00:40 UTC 
I believe this is the same issue:

19:30:23,145 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-19,shared=udp) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on ZBuqKMaRJ1fcGVrUGlDT-izr on behalf of transaction GlobalTransaction:<perf21/web>:41758:remote. Lock is being held by null
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:217)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.waitForTransactionsToComplete(AbstractTxLockingInterceptor.java:210)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:174)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:123)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.lockAndRecord(OptimisticLockingInterceptor.java:254)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitSingleKeyCommand(OptimisticLockingInterceptor.java:249)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:242)
	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:335)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:123)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:58)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:128)
	at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:115)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:58)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216)
	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:189)
	at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:93)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
	at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:70)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
	at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:119)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:101)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:122)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:86)
	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:247)
	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220)
	at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484)
	at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391)
	at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249)
	at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:598)
	at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
	at org.jgroups.JChannel.up(JChannel.java:707)
	at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
	at org.jgroups.protocols.RSVP.up(RSVP.java:188)
	at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
	at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
	at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
	at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
	at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245)
	at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:765)
	at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
	at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:606)
	at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
	at org.jgroups.protocols.FD.up(FD.java:253)
	at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
	at org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
	at org.jgroups.protocols.Discovery.up(Discovery.java:359)
	at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2616)
	at org.jgroups.protocols.TP.passMessageUp(TP.java:1263)
	at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1825)
	at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1798)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_38]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_38]
	at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_38]

Seen in https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-dist-sync/39/console-perf18/

Therefore, this still affects EAP 6.1.0.ER2.
Comment 4 Ladislav Thon 2013-05-14 14:25:17 UTC 
Still seeing this with EAP 6.1.0.ER8. For example:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-undeploy-repl-sync/54/artifact/report/config/jboss-perf18/server.log
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-ejb-ejbremote-shutdown-repl-sync/24/artifact/report/config/jboss-perf21/server.log
Comment 5 Ladislav Thon 2013-08-26 12:54:47 UTC 
Still seeing this with EAP 6.1.1.ER7. For example:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-ejb-ejbservlet-shutdown-repl-sync/15/
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-netDown-dist-sync/15/
Comment 6 Paul Ferraro 2013-12-06 14:05:28 UTC 
This needs to be retested.  EAP 6.3 uses pessimistic locking.
Comment 7 Richard Janík 2013-12-09 09:53:29 UTC 
Thanks for update, we'll retest it with 6.3.0 when we get a build.

To summarize: we've seen this in 6.2.0.CR3 as well (GA), it seems to be specific to SYNC cache.
Comment 8 Paul Ferraro 2013-12-13 13:04:53 UTC 
I meant that 6.2 uses pessimistic locking - so please retest against 6.2.0.GA
Comment 9 Richard Janík 2013-12-19 08:55:14 UTC 
It was seen with 6.2.0.GA.

Link to sample build:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-repl-sync/66/

Links to logs:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-repl-sync/66/artifact/report/config/jboss-perf19/server.log
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-repl-sync/66/artifact/report/config/jboss-perf20/server.log

Stacktrace:

08:19:11,376 ERROR [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-408,shared=udp) Exception executing command: org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on bk7RLTN0hin40WhEXi0twcrJ on behalf of transaction GlobalTransaction:<perf19/web>:41229:remote. Lock is being held by GlobalTransaction:<perf19/web>:18043:remote
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:218)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.waitForTransactionsToComplete(AbstractTxLockingInterceptor.java:211)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:175)
	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:124)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.lockAndRecord(OptimisticLockingInterceptor.java:254)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitSingleKeyCommand(OptimisticLockingInterceptor.java:249)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:242)
	at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:335)
	at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:123)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
	at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:58)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
	at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:128)
	at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:115)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	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.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitPrepareCommand(TransactionSynchronizerInterceptor.java:58)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
	at org.infinispan.statetransfer.StateTransferInterceptor.handleTopologyAffectedCommand(StateTransferInterceptor.java:216)
	at org.infinispan.statetransfer.StateTransferInterceptor.handleTxCommand(StateTransferInterceptor.java:189)
	at org.infinispan.statetransfer.StateTransferInterceptor.visitPrepareCommand(StateTransferInterceptor.java:93)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	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.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
	at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
	at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:126)
	at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
	at org.infinispan.commands.tx.PrepareCommand.perform(PrepareCommand.java:119)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:101)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:122)
	at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:86)
	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:247)
	at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220)
	at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484)
	at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391)
	at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249)
	at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:600)
	at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
	at org.jgroups.JChannel.up(JChannel.java:707)
	at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1025)
	at org.jgroups.protocols.RSVP.up(RSVP.java:188)
	at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
	at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
	at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
	at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
	at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245)
	at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:453)
	at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:751)
	at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:609)
	at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:147)
	at org.jgroups.protocols.FD.up(FD.java:253)
	at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
	at org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
	at org.jgroups.protocols.Discovery.up(Discovery.java:359)
	at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2607)
	at org.jgroups.protocols.TP.passMessageUp(TP.java:1260)
	at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1822)
	at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1795)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895) [rt.jar:1.6.0_45]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918) [rt.jar:1.6.0_45]
	at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_45]
Comment 10 Radoslav Husar 2013-12-19 09:10:42 UTC 
Starting ack process for 6.3.
Comment 11 Paul Ferraro 2014-02-10 19:21:26 UTC 
Please retest after Infinispan 5.2.8 upgrade.
Comment 12 Richard Janík 2014-03-04 14:26:49 UTC 
Retested against 6.3.0.DR1, still present (one configuration only):

remote EJBs, shutdown, dist sync cache:
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-ejb-ejbremote-shutdown-dist-sync-3owners/28/console-perf19/
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-ejb-ejbremote-shutdown-dist-sync-3owners/28/console-perf21/
Comment 15 Scott Mumford 2014-07-17 04:30:31 UTC 
Removing privacy flags for inclusion in 6.3.0 Release Notes as a Known Issue.
Comment 18 Radoslav Husar 2014-11-05 13:59:21 UTC 
Can we get an update from QE what this looks like in 6.4? Is it only for the configuration remote EJBs, shutdown, dist, sync as per comment #12?
Comment 19 Paul Ferraro 2014-11-07 18:47:01 UTC 
Hmmm.  Something is amiss here.  We should be using pessimistic locking as of EAP 6.2 (#c8), yet I can't find a commit in git history that would have changed this.  Furthermore, the stack trace in #c9 indicates that the caches are configure with OPTIMISTIC locking (the lock timeout happens during prepare (which cannot be the case with PESSIMISTIC locking).

Please retest adding the following to the cache configurations for the web and ejb caches:

<transaction locking="PESSIMISTIC"/>

If all looks good, I'll modify the default configuration accordingly.  I'm going to ACK this for now.
Comment 20 Ladislav Thon 2014-11-14 13:42:54 UTC 
In response to comment 18:

This seems to be very rare. During DR4, we saw this in 2 cases:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-ejb-ejbremote-shutdown-dist-sync-3owners/42/
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-dist-async-3owners/42/

During DR5, in only 1 case:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-undeploy-repl-sync/88/

And during DR9, in only 1 case as well:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-dist-async/77/

There is no pattern here, this happens in all sorts of scenarios.
Comment 21 Paul Ferraro 2014-11-19 00:08:10 UTC 
Still waiting on feedback from #c19.
Comment 22 Ladislav Thon 2014-11-20 07:41:37 UTC 
Just noting that I am working on it, but this occurs rarely, so it will take more time than I thought.
Comment 23 Ladislav Thon 2014-11-24 12:55:38 UTC 
In response to comment 19:

I chose the eap-6x-failover-ejb-ejbremote-shutdown-dist-sync-3owners scenario and ran it 20 times with DR9. This issue occured twice in those 20 runs.

Then, I adjusted the configuration as described above and ran the test again. It was looking nice, first 20 runs were OK, and then this issue occured again.

See https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/lthon___bz-901162___eap-6x-failover-ejb-ejbremote-shutdown-dist-sync-3owners/46/

- configurations of all the servers are available in Build Artifacts under report/config/jboss-perf{18,19,20,21}/standalone-ha.xml
- the exception is visible in logs of perf18 and perf21

You will also note that lock acquisition timeout happens in PessimisticLockingInterceptor.visitLockControlCommand, so that's a different cause than suspected.
Comment 24 Peter Wallstedt 2014-11-27 09:15:15 UTC 
I'm _very_ interested to know how this is going.

we're running 6.1.1 with Infinsipan 5.2.7 and we see this problem as well.
Running a two node cluster with light load, it takes about 10 hours before the TimeOut happens, running it a bit harder, it takes two minutes. It always pops up though.
We've tested all kinds of configuration changes, with no success.

I don't know how this forum is supposed to be used, so I apologize in advance if I'm misusing it somehow!
Comment 25 Paul Ferraro 2014-12-01 18:39:35 UTC 
Ladislav,
How many SFSBs have been created by the test when you start to see timeouts?  I suspect that when the number of active cache entries is sufficiently large then state transfer is going taking longer than the default lock acquisition timeout (15 seconds).  The state transfer costs increase significantly if the passivation threshold of the store is reached (i.e. 10000 entries, by default).

You can increase the default lock timeout via:

<locking acquire-timeout="<timeout-value-in-milliseconds>"/>

I suggest increasing this to match the anticipated state transfer duration.
Comment 26 Ladislav Thon 2014-12-02 10:31:17 UTC 
Paul,

I went through all the failing tests from comment 20 and comment 23 and the failures always happen when the test is long in progress. Given that all the failover tests run 2000 clients right from the beginning, no more, no less, there should always be 2000 SFSBs when timeouts are starting to occur. I'm not sure if this is too much to cause state transfer taking too long.

-----

Side note: I also noticed that in the HTTP-related scenarios from comment 20, the failures are from OptimisticLockingInterceptor, so that cause is still not ruled out. See [1] [2] [3].

Maybe we should have a different bug for that? In any way, I will pick one of the HTTP-related scenarios and try switching to pessimistic locking. I'll comment here once I have some results (which might take long).

[1] https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-dist-async-3owners/42/console-perf18/

[2] https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-undeploy-repl-sync/88/console-perf18/

[3] https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-jvmkill-dist-async/77/console-perf21/
Comment 27 Kabir Khan 2014-12-12 10:52:27 UTC 
Devel-nacking since there is no longer time to do this in the 6.4.0 time frame, and it is not a blocker
Comment 29 Peter Palaga 2016-11-25 16:36:51 UTC 
Closing for reasons named in Comment#27
Note You need to log in before you can comment on or make changes to this bug.