901162 – (JBPAPP6-1275) [GSS](6.4.z) TimeoutException: Unable to acquire lock

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
Sub Component:
Version:	6.1.1,6.2.0,6.3.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	urgent
Severity:	high
Target Milestone:	GA
Target Release:	---
Assignee:	Paul Ferraro
QA Contact:	Ladislav Thon
Docs Contact:	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)
CC List:	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	Priority	Status	Summary	Last Updated
JBoss Issue Tracker	JBPAPP6-1275	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.