Bug 1373412 - [GSS](6.4.z) TimeoutException when request ends up on non-coordinator node (invalidation cache, web session passivation and shared cache store)
[GSS](6.4.z) TimeoutException when request ends up on non-coordinator node (i...
Status: VERIFIED
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: Clustering (Show other bugs)
6.4.8
Unspecified Unspecified
high Severity high
: CR1
: EAP 6.4.19
Assigned To: Jiri Ondrusek
Michal Vinkler
:
Depends On:
Blocks: 1466978 eap6419-payload eap6411-payload
  Show dependency treegraph
 
Reported: 2016-09-06 04:19 EDT by Ladislav Thon
Modified: 2018-01-04 05:38 EST (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
testing deployment (2.79 KB, application/zip)
2016-09-06 04:19 EDT, Ladislav Thon
no flags Details

  None (edit)
Description Ladislav Thon 2016-09-06 04:19:25 EDT
Created attachment 1198123 [details]
testing deployment

Description of problem:

Configure an EAP cluster with an invalidation cache + a shared cache store (e.g. a remote JDG cluster or a shared file store). Deploy a distributable web app and enable web session passivation in jboss-web.xml.

Then send an HTTP request to a non-coordinator node of the cluster. The node will log a bunch of remote exceptions during invalidation processing. The remote exceptions are "TimeoutException: Unable to acquire lock".

Version-Release number of selected component (if applicable):

EAP 6.4.8

How reproducible:

Always

Steps to Reproduce:
1. unzip jboss-eap-6.4.0.zip
2. ./jboss-eap-6.4/bin/jboss-cli.sh --command="patch apply jboss-eap-6.4.8-patch.zip"
3. ./jboss-eap-6.4/bin/standalone.sh -c standalone-ha.xml
4. ./jboss-eap-6.4/bin/jboss-cli.sh -c

/subsystem=infinispan/cache-container=web/invalidation-cache=offload:add(mode=SYNC, batching=true)

/subsystem=infinispan/cache-container=web/invalidation-cache=offload/file-store=FILE_STORE:add(path=/tmp/eap-shared-cache-store, shared=true, preload=false, purge=false, passivation=false)

shutdown

5. cp tinyClusteredWebapp.war jboss-eap-6.4/standalone/deployments/ # attached
6. mv jboss-eap-6.4/ jboss-eap-6.4-node1
7. cp -a jboss-eap-6.4-node1 jboss-eap-6.4-node2
8. ./jboss-eap-6.4-node1/bin/standalone.sh -c standalone-ha.xml -Djboss.node.name=node1
9. ./jboss-eap-6.4-node2/bin/standalone.sh -c standalone-ha.xml -Djboss.node.name=node2 -Djboss.socket.binding.port-offset=100
10. curl -v  http://localhost:8180/tinyClusteredWebapp/

Actual results:

Exceptions logged on both cluster nodes. The request takes a lot of time to process, waiting for timeout.

Expected results:

No exceptions logged. No timeouts.

Additional info:

This is specific to EAP 6. Upstream / EAP 7 has a completely different web session clustering implementation.
Comment 2 Ladislav Thon 2016-09-08 09:42:50 EDT
I was asked to provide a stack trace. Here are the relevant parts of the logs:

----- on the coordinator -----

15:41:22,899 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (OOB-19,shared=udp) ISPN000136: Execution error: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [ahHlOUxiY79VGB0ND2cisa6x] for requestor [Thread[OOB-19,shared=udp,5,ServerService ThreadGroup]]! Lock held by [GlobalTransaction:<node2/web>:1:remote]
        at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:213)
        at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
        at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
        at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
        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: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:766)
        at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
        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.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_101]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]

15:41:22,904 ERROR [org.infinispan.remoting.InboundInvocationHandlerImpl] (OOB-19,shared=udp) Exception executing command: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [ahHlOUxiY79VGB0ND2cisa6x] for requestor [Thread[OOB-19,shared=udp,5,ServerService ThreadGroup]]! Lock held by [GlobalTransaction:<node2/web>:1:remote]
        at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:213)
        at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
        at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
        at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
        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: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:766)
        at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
        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.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_101]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]

----- on the non-coordinator node that received the request -----

15:41:22,918 WARN  [org.infinispan.interceptors.InvalidationInterceptor] (http-127.0.0.1:8180-1) Unable to broadcast evicts as a part of the prepare phase.  Rolling back.: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from node1/web, see cause for remote stack trace
        at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:60)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:310)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:179)
        at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:515)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:173)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:194)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:251)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:238)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:233)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:212)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:204)
        at org.infinispan.interceptors.InvalidationInterceptor.invalidateAcrossCluster(InvalidationInterceptor.java:283)
        at org.infinispan.interceptors.InvalidationInterceptor.broadcastInvalidateForPrepare(InvalidationInterceptor.java:211)
        at org.infinispan.interceptors.InvalidationInterceptor.visitPrepareCommand(InvalidationInterceptor.java:145)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.CacheStoreInterceptor.visitPrepareCommand(CacheStoreInterceptor.java:208)
        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.EntryWrappingInterceptor.visitPrepareCommand(EntryWrappingInterceptor.java:111)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.invokeNextAndCommitIf1Pc(AbstractTxLockingInterceptor.java:109)
        at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitPrepareCommand(PessimisticLockingInterceptor.java:106)
        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.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:92)
        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.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:175)
        at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
        at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
        at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
        at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
        at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
        at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
        at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1574) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:872) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:142) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:99) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:92) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:64) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]
Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [ahHlOUxiY79VGB0ND2cisa6x] for requestor [Thread[OOB-19,shared=udp,5,ServerService ThreadGroup]]! Lock held by [GlobalTransaction:<node2/web>:1:remote]
        at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:213)
        at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
        at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
        at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
        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: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:766)
        at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
        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.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_101]
        ... 1 more

15:41:22,927 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http-127.0.0.1:8180-1) ISPN000136: Execution error: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from node1/web, see cause for remote stack trace
        at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:60)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:310)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:179)
        at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:515)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:173)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:194)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:251)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:238)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:233)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:212)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:204)
        at org.infinispan.interceptors.InvalidationInterceptor.invalidateAcrossCluster(InvalidationInterceptor.java:283)
        at org.infinispan.interceptors.InvalidationInterceptor.broadcastInvalidateForPrepare(InvalidationInterceptor.java:211)
        at org.infinispan.interceptors.InvalidationInterceptor.visitPrepareCommand(InvalidationInterceptor.java:145)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.CacheStoreInterceptor.visitPrepareCommand(CacheStoreInterceptor.java:208)
        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.EntryWrappingInterceptor.visitPrepareCommand(EntryWrappingInterceptor.java:111)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.invokeNextAndCommitIf1Pc(AbstractTxLockingInterceptor.java:109)
        at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitPrepareCommand(PessimisticLockingInterceptor.java:106)
        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.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:92)
        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.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:175)
        at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
        at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
        at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
        at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
        at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
        at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
        at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1574) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:872) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:142) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:99) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:92) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:64) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]
Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [ahHlOUxiY79VGB0ND2cisa6x] for requestor [Thread[OOB-19,shared=udp,5,ServerService ThreadGroup]]! Lock held by [GlobalTransaction:<node2/web>:1:remote]
        at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:213)
        at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
        at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
        at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
        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: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:766)
        at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
        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.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_101]
        ... 1 more

15:41:22,934 ERROR [org.infinispan.transaction.TransactionCoordinator] (http-127.0.0.1:8180-1) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from node1/web, see cause for remote stack trace
        at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:60)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:310)
        at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:179)
        at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:515)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:173)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:194)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:251)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:238)
        at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:233)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:212)
        at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:204)
        at org.infinispan.interceptors.InvalidationInterceptor.invalidateAcrossCluster(InvalidationInterceptor.java:283)
        at org.infinispan.interceptors.InvalidationInterceptor.broadcastInvalidateForPrepare(InvalidationInterceptor.java:211)
        at org.infinispan.interceptors.InvalidationInterceptor.visitPrepareCommand(InvalidationInterceptor.java:145)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.CacheStoreInterceptor.visitPrepareCommand(CacheStoreInterceptor.java:208)
        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.EntryWrappingInterceptor.visitPrepareCommand(EntryWrappingInterceptor.java:111)
        at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.invokeNextAndCommitIf1Pc(AbstractTxLockingInterceptor.java:109)
        at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitPrepareCommand(PessimisticLockingInterceptor.java:106)
        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.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:92)
        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.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:175)
        at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
        at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
        at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
        at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
        at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
        at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
        at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1574) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:872) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:142) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:99) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:92) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:64) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]
Caused by: org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [15 seconds] on key [ahHlOUxiY79VGB0ND2cisa6x] for requestor [Thread[OOB-19,shared=udp,5,ServerService ThreadGroup]]! Lock held by [GlobalTransaction:<node2/web>:1:remote]
        at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:213)
        at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
        at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        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.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
        at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
        at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
        at org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
        at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
        at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
        at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
        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: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:766)
        at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
        at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
        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.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_101]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_101]
        ... 1 more

15:41:22,940 ERROR [org.infinispan.transaction.tm.DummyTransaction] (http-127.0.0.1:8180-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=[node1/web, node2/web], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=[ahHlOUxiY79VGB0ND2cisa6x], topologyId=2, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1} org.infinispan.transaction.synchronization.SynchronizationAdapter@20: org.infinispan.CacheException: Could not commit.
        at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:83)
        at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:285)
        at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:334)
        at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:91)
        at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
        at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
        at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1574) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:872) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:142) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:99) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:92) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:64) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.5.8.Final-redhat-2.jar:7.5.8.Final-redhat-2]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_101]
Caused by: javax.transaction.xa.XAException
        at org.infinispan.transaction.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:224)
        at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:177)
        at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
        ... 21 more
Comment 3 Paul Ferraro 2016-09-08 10:37:26 EDT
https://github.com/jbossas/jboss-eap/pull/2837
Comment 4 Paul Ferraro 2016-09-08 13:49:00 EDT
Amended commit: https://github.com/jbossas/jboss-eap/pull/2838
Comment 5 Ladislav Thon 2016-09-09 04:45:49 EDT
I built EAP 6.4.8 with the patch from PR 2838 and it didn't help, the stack traces are still the same.

Looking at the proposed fix, it looks like it prevents the request-handling node from locking the key during session eviction. However, the problem here happens during session creation.

I used these Byteman rules:

RULE Infinispan acquiring lock
CLASS org.infinispan.util.concurrent.locks.LockManagerImpl
METHOD lock
AT ENTRY
IF true
DO traceStack("!!!!!!!!!!!!!!!!!!! acquiring lock for key " + $2 + "\n", 100)
ENDRULE

RULE Infinispan acquired lock
CLASS org.infinispan.util.concurrent.locks.LockManagerImpl
METHOD lock
AT EXIT
IF true
DO traceln("!!!!!!!!!!!!!!!!!!! acquired lock for key " + $2)
ENDRULE

RULE Infinispan failed to acquire lock
CLASS org.infinispan.util.concurrent.locks.LockManagerImpl
METHOD lock
AT EXCEPTION EXIT
IF true
DO traceln("!!!!!!!!!!!!!!!!!!! failed to acquired lock for key " + $2)
ENDRULE

Here are the logs from these Byteman rules:

----- on the coordinator -----

10:23:27,708 INFO  [stdout] (OOB-20,shared=udp) Rule.execute called for Infinispan acquiring lock_0
10:23:27,710 INFO  [stdout] (OOB-20,shared=udp) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,711 INFO  [stdout] (OOB-20,shared=udp) calling activated() for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,711 INFO  [stdout] (OOB-20,shared=udp) Default helper activated
10:23:27,711 INFO  [stdout] (OOB-20,shared=udp) calling installed(Infinispan acquiring lock) for helper classorg.jboss.byteman.rule.helper.Helper
10:23:27,711 INFO  [stdout] (OOB-20,shared=udp) Installed rule using default helper : Infinispan acquiring lock
10:23:27,711 INFO  [stdout] (OOB-20,shared=udp) Infinispan acquiring lock execute()
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) !!!!!!!!!!!!!!!!!!! acquiring lock for key B5Daw4KVa+smEQ-vOqOuioI8
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:-1)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:186)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:192)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:129)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitLockControlCommand(PessimisticLockingInterceptor.java:253)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
10:23:27,712 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:128)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.TxInterceptor.visitLockControlCommand(TxInterceptor.java:186)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InvocationContextInterceptor.visitLockControlCommand(InvocationContextInterceptor.java:97)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.AbstractVisitor.visitLockControlCommand(AbstractVisitor.java:177)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.acceptVisitor(LockControlCommand.java:131)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.control.LockControlCommand.perform(LockControlCommand.java:150)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
10:23:27,713 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:247)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:600)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.JChannel.up(JChannel.java:707)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1025)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.RSVP.up(RSVP.java:188)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
10:23:27,714 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:766)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:147)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FD.up(FD.java:253)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.Discovery.up(Discovery.java:359)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2607)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP.passMessageUp(TP.java:1260)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1822)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1795)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
10:23:27,715 INFO  [stdout] (OOB-20,shared=udp) java.lang.Thread.run(Thread.java:745)
10:23:27,717 INFO  [stdout] (OOB-20,shared=udp) Rule.execute called for Infinispan acquired lock_2
10:23:27,717 INFO  [stdout] (OOB-20,shared=udp) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,717 INFO  [stdout] (OOB-20,shared=udp) calling installed(Infinispan acquired lock) for helper classorg.jboss.byteman.rule.helper.Helper
10:23:27,717 INFO  [stdout] (OOB-20,shared=udp) Installed rule using default helper : Infinispan acquired lock
10:23:27,718 INFO  [stdout] (OOB-20,shared=udp) Infinispan acquired lock execute()
10:23:27,718 INFO  [stdout] (OOB-20,shared=udp) !!!!!!!!!!!!!!!!!!! acquired lock for key B5Daw4KVa+smEQ-vOqOuioI8
10:23:27,764 INFO  [stdout] (OOB-20,shared=udp) Rule.execute called for Infinispan acquiring lock_0
10:23:27,764 INFO  [stdout] (OOB-20,shared=udp) Infinispan acquiring lock execute()
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) !!!!!!!!!!!!!!!!!!! acquiring lock for key B5Daw4KVa+smEQ-vOqOuioI8
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:-1)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLockNoCheck(LockManagerImpl.java:196)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockKey(AbstractLockingInterceptor.java:114)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateCommand(AbstractLockingInterceptor.java:66)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:255)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,765 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:76)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:136)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:61)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:70)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handleInternal(InboundInvocationHandlerImpl.java:100)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handleWithWaitForBlocks(InboundInvocationHandlerImpl.java:121)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:85)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:247)
10:23:27,766 INFO  [stdout] (OOB-20,shared=udp) org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:600)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.JChannel.up(JChannel.java:707)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1025)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.RSVP.up(RSVP.java:188)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245)
10:23:27,767 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:766)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.UNICAST2.up(UNICAST2.java:420)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:645)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:147)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FD.up(FD.java:253)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.Discovery.up(Discovery.java:359)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2607)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP.passMessageUp(TP.java:1260)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1822)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1795)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
10:23:27,768 INFO  [stdout] (OOB-20,shared=udp) java.lang.Thread.run(Thread.java:745)
10:23:42,771 INFO  [stdout] (OOB-20,shared=udp) Rule.execute called for Infinispan failed to acquire lock_4
10:23:42,774 INFO  [stdout] (OOB-20,shared=udp) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
10:23:42,774 INFO  [stdout] (OOB-20,shared=udp) calling installed(Infinispan failed to acquire lock) for helper classorg.jboss.byteman.rule.helper.Helper
10:23:42,775 INFO  [stdout] (OOB-20,shared=udp) Installed rule using default helper : Infinispan failed to acquire lock
10:23:42,776 INFO  [stdout] (OOB-20,shared=udp) Infinispan failed to acquire lock execute()
10:23:42,776 INFO  [stdout] (OOB-20,shared=udp) !!!!!!!!!!!!!!!!!!! failed to acquired lock for key B5Daw4KVa+smEQ-vOqOuioI8

----- on the non-coordinator node that received the request -----

10:23:27,721 INFO  [stdout] (http-127.0.0.1:8180-1) Rule.execute called for Infinispan acquiring lock_0
10:23:27,724 INFO  [stdout] (http-127.0.0.1:8180-1) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,724 INFO  [stdout] (http-127.0.0.1:8180-1) calling activated() for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,724 INFO  [stdout] (http-127.0.0.1:8180-1) Default helper activated
10:23:27,724 INFO  [stdout] (http-127.0.0.1:8180-1) calling installed(Infinispan acquiring lock) for helper classorg.jboss.byteman.rule.helper.Helper
10:23:27,725 INFO  [stdout] (http-127.0.0.1:8180-1) Installed rule using default helper : Infinispan acquiring lock
10:23:27,725 INFO  [stdout] (http-127.0.0.1:8180-1) Infinispan acquiring lock execute()
10:23:27,725 INFO  [stdout] (http-127.0.0.1:8180-1) !!!!!!!!!!!!!!!!!!! acquiring lock for key B5Daw4KVa+smEQ-vOqOuioI8
10:23:27,725 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:-1)
10:23:27,725 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:186)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:192)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitGetKeyValueCommand(PessimisticLockingInterceptor.java:93)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:58)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:134)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:104)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:58)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:231)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:226)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:58)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
10:23:27,726 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:104)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:58)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:120)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:92)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:104)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:58)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.CacheImpl.get(CacheImpl.java:289)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.DecoratedCache.get(DecoratedCache.java:315)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.AbstractDelegatingCache.get(AbstractDelegatingCache.java:303)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.atomic.AtomicHashMapProxy.getDeltaMapForWrite(AtomicHashMapProxy.java:133)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.infinispan.atomic.AtomicHashMapProxy.put(AtomicHashMapProxy.java:207)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.web.infinispan.SessionMapEntry.put(SessionMapEntry.java:70)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.web.infinispan.DistributedCacheManager$1.invoke(DistributedCacheManager.java:173)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.web.infinispan.DistributedCacheManager$1.invoke(DistributedCacheManager.java:168)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.infinispan.invoker.SimpleCacheInvoker.invoke(SimpleCacheInvoker.java:34)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.infinispan.invoker.BatchCacheInvoker.invoke(BatchCacheInvoker.java:48)
10:23:27,727 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.infinispan.invoker.RetryingCacheInvoker.invoke(RetryingCacheInvoker.java:85)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.web.infinispan.DistributedCacheManager$ForceSynchronousCacheInvoker.invoke(DistributedCacheManager.java:552)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.clustering.web.infinispan.DistributedCacheManager.storeSessionData(DistributedCacheManager.java:185)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.ClusteredSession.processSessionReplication(ClusteredSession.java:1064)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1556)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:872)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:142)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:99)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:92)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:64)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854)
10:23:27,728 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654)
10:23:27,729 INFO  [stdout] (http-127.0.0.1:8180-1) org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926)
10:23:27,729 INFO  [stdout] (http-127.0.0.1:8180-1) java.lang.Thread.run(Thread.java:745)
10:23:27,730 INFO  [stdout] (http-127.0.0.1:8180-1) Rule.execute called for Infinispan acquired lock_2
10:23:27,731 INFO  [stdout] (http-127.0.0.1:8180-1) HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper
10:23:27,731 INFO  [stdout] (http-127.0.0.1:8180-1) calling installed(Infinispan acquired lock) for helper classorg.jboss.byteman.rule.helper.Helper
10:23:27,731 INFO  [stdout] (http-127.0.0.1:8180-1) Installed rule using default helper : Infinispan acquired lock
10:23:27,732 INFO  [stdout] (http-127.0.0.1:8180-1) Infinispan acquired lock execute()
10:23:27,732 INFO  [stdout] (http-127.0.0.1:8180-1) !!!!!!!!!!!!!!!!!!! acquired lock for key B5Daw4KVa+smEQ-vOqOuioI8

I know I should probably add some rules to print unlocks as well, but even from this, it looks like

1. the coordinator locks the key successfully (LockControlCommand)
2. the request-handling node locks the key successfully (DistributableSessionManager.storeSession > DistributedCacheManager.storeSessionData > SessionMapEntry.put > GetKeyValueCommand)
3. the coordinator tries to lock the key again (InvalidateCommand), but fails
Comment 6 Paul Ferraro 2016-09-09 09:45:27 EDT
@lthon@redhat.com Question - the attached config does not appear to set a value for <max-active-sessions/>.  Session creation only triggers pre-emptive passivation if there is a max-active-session value specified.  Are we absolutely sure this isn't the case?

In EAP6, you would never need to set a max-active-sessions if you have passivation enabled.
Comment 7 Ladislav Thon 2016-09-09 10:05:14 EDT
Paul, I'm using the exact application that is attached to this BZ. So yes, max-active-sessions is not set.

I don't think that the problem is caused by pre-emptive passivation -- see the stack traces in comment 5. Looking at ClusteredSessionValve.handleRequest:142, I was obviously wrong about the problem happening during session creation, it's after the request was processed, when the session is stored to the cache.
Comment 8 Jiří Bílek 2016-10-06 11:35:20 EDT
Many thanks for detailed "Steps to Reproduce".
Reopened because reproducer gets exception as well in 6.4.11.CP.CR1. From comment #5 was not provided new fix so it still does not work.
Comment 12 Jiří Bílek 2018-01-04 05:38:51 EST
Verified with EAP 6.4.19.CP.CR1

Note You need to log in before you can comment on or make changes to this bug.