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
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).
Docs QE Status: Removed: NEW
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.
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
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/
This needs to be retested. EAP 6.3 uses pessimistic locking.
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.
I meant that 6.2 uses pessimistic locking - so please retest against 6.2.0.GA
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]
Starting ack process for 6.3.
Please retest after Infinispan 5.2.8 upgrade.
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/
Removing privacy flags for inclusion in 6.3.0 Release Notes as a Known Issue.
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?
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.
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.
Still waiting on feedback from #c19.
Just noting that I am working on it, but this occurs rarely, so it will take more time than I thought.
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.
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!
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.
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/
Devel-nacking since there is no longer time to do this in the 6.4.0 time frame, and it is not a blocker
Closing for reasons named in Comment#27