]
Radoslav Husar closed AS7-4724.
-------------------------------
Resolution: Done
I have tested this and its fixed. Closing.
Sessions lost on server crash when using DIST SYNC mode (Lock is
being held by null)
------------------------------------------------------------------------------------
Key: AS7-4724
URL:
https://issues.jboss.org/browse/AS7-4724
Project: Application Server 7
Issue Type: Bug
Components: Clustering
Affects Versions: 7.1.1.Final
Reporter: Radoslav Husar
Assignee: Paul Ferraro
Priority: Critical
Labels: failover_testing
Fix For: 7.1.3.Final (EAP)
It seems that the current failover tests have few failed requests when using DIST SYNC.
The client logging indicates that
{noformat}2012/05/06 17:04:20:041 EDT [WARN ][Runner - 123] HOST
perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:
<org.jboss.smartfrog.loaddriver.RequestProcessingException: Stale session data
received. Expected 100, received 0, Runner: 123>{noformat}
that the session was not found and created a new session instead.
The exceptions sorroundthing the errors
{noformat}
[JBossINF] 16:55:52,535 INFO
[org.jboss.test.clusterbench.common.session.CommonHttpSessionServlet]
(ajp-perf21-10.16.90.60-8009-44) New session created: -gjLvzZ7CdxcPVSlMbL1A1bK.perf21
2012/05/06 16:56:22:030 EDT [DEBUG][Thread-28] HOST
perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - JBossStartup, server started!
[JBossINF] 16:57:49,978 INFO [org.jboss.as.clustering] (Incoming-10,null) JBAS010226:
New cluster view for partition ejb: 4
(org.jboss.as.clustering.impl.CoreGroupCommunicationService$GroupView@6232c7b5 delta: -1,
merge: false)
[JBossINF] 16:57:49,980 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-10,null)
ISPN000094: Received new cluster view: [perf19/ejb|4] [perf19/ejb, perf21/ejb,
perf20/ejb]
[JBossINF] 16:57:49,980 INFO [org.jboss.as.clustering] (Incoming-2,null) JBAS010226: New
cluster view for partition web: 4
(org.jboss.as.clustering.impl.CoreGroupCommunicationService$GroupView@27782e36 delta: -1,
merge: false)
[JBossINF] 16:57:49,981 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-2,null) ISPN000094:
Received new cluster view: [perf19/web|4] [perf19/web, perf21/web, perf20/web]
[JBossINF] 16:58:52,192 INFO [org.jboss.as.clustering] (Incoming-19,null) JBAS010226:
New cluster view for partition web: 5
(org.jboss.as.clustering.impl.CoreGroupCommunicationService$GroupView@2d942191 delta: 1,
merge: false)
[JBossINF] 16:58:52,192 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-19,null)
ISPN000094: Received new cluster view: [perf19/web|5] [perf19/web, perf21/web, perf20/web,
perf18/web]
[JBossINF] 16:58:52,256 INFO [org.jboss.as.clustering] (Incoming-18,null) JBAS010226:
New cluster view for partition ejb: 5
(org.jboss.as.clustering.impl.CoreGroupCommunicationService$GroupView@2f94ac91 delta: 1,
merge: false)
[JBossINF] 16:58:52,257 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-18,null)
ISPN000094: Received new cluster view: [perf19/ejb|5] [perf19/ejb, perf21/ejb, perf20/ejb,
perf18/ejb]
[JBossINF] 16:59:56,589 INFO [org.jboss.as.clustering]
(VERIFY_SUSPECT.TimerThread,web,perf21/web) JBAS010232: Suspected member: perf19/web
[JBossINF] 16:59:56,589 INFO [org.jboss.as.clustering]
(VERIFY_SUSPECT.TimerThread,ejb,perf21/ejb) JBAS010232: Suspected member: perf19/ejb
[JBossINF] 16:59:56,694 INFO [org.jboss.as.clustering] (Incoming-11,null) JBAS010225:
New cluster view for partition ejb (id: 6, delta: -1, merge: false) : [perf21/ejb,
perf20/ejb, perf18/ejb]
[JBossINF] 16:59:56,694 INFO [org.jboss.as.clustering] (Incoming-1,null) JBAS010225: New
cluster view for partition web (id: 6, delta: -1, merge: false) : [perf21/web, perf20/web,
perf18/web]
[JBossINF] 16:59:56,695 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-11,null)
ISPN000094: Received new cluster view: [perf21/ejb|6] [perf21/ejb, perf20/ejb,
perf18/ejb]
[JBossINF] 16:59:56,695 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-1,null) ISPN000094:
Received new cluster view: [perf21/web|6] [perf21/web, perf20/web, perf18/web]
[JBossINF] 17:00:58,915 INFO [org.jboss.as.clustering] (Incoming-7,null) JBAS010225: New
cluster view for partition web (id: 7, delta: 1, merge: false) : [perf21/web, perf20/web,
perf18/web, perf19/web]
[JBossINF] 17:00:58,916 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-7,null) ISPN000094:
Received new cluster view: [perf21/web|7] [perf21/web, perf20/web, perf18/web,
perf19/web]
[JBossINF] 17:00:58,974 INFO [org.jboss.as.clustering] (Incoming-4,null) JBAS010225: New
cluster view for partition ejb (id: 7, delta: 1, merge: false) : [perf21/ejb, perf20/ejb,
perf18/ejb, perf19/ejb]
[JBossINF] 17:00:58,974 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,null) ISPN000094:
Received new cluster view: [perf21/ejb|7] [perf21/ejb, perf20/ejb, perf18/ejb,
perf19/ejb]
[JBossINF] 17:02:02,386 INFO [org.jboss.as.clustering]
(VERIFY_SUSPECT.TimerThread,ejb,perf21/ejb) JBAS010232: Suspected member: perf20/ejb
[JBossINF] 17:02:02,387 INFO [org.jboss.as.clustering]
(VERIFY_SUSPECT.TimerThread,web,perf21/web) JBAS010232: Suspected member: perf20/web
[JBossINF] 17:02:02,445 INFO [org.jboss.as.clustering] (Incoming-5,null) JBAS010225: New
cluster view for partition web (id: 8, delta: -1, merge: false) : [perf21/web, perf18/web,
perf19/web]
[JBossINF] 17:02:02,450 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-5,null) ISPN000094:
Received new cluster view: [perf21/web|8] [perf21/web, perf18/web, perf19/web]
[JBossINF] 17:02:02,463 INFO [org.jboss.as.clustering] (Incoming-4,null) JBAS010225: New
cluster view for partition ejb (id: 8, delta: -1, merge: false) : [perf21/ejb, perf18/ejb,
perf19/ejb]
[JBossINF] 17:02:02,463 INFO
[org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-4,null) ISPN000094:
Received new cluster view: [perf21/ejb|8] [perf21/ejb, perf18/ejb, perf19/ejb]
[JBossINF] 17:02:21,486 ERROR [org.infinispan.interceptors.InvocationContextInterceptor]
(ajp-perf21-10.16.90.60-8009-104) ISPN000136: Execution error:
org.infinispan.util.concurrent.TimeoutException: Could not acquire lock on
x2pULjT0wz2pS0AC1l0Osck6 on behalf of transaction
GlobalTransaction:<perf21/web>:5824:remote. Lock is being held by null
[JBossINF] at
org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.newTimeoutException(AbstractTxLockingInterceptor.java:214)
[JBossINF] at
org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:195)
[JBossINF] at
org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:136)
[JBossINF] at
org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:243)
[JBossINF] at
org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:77)
[JBossINF] at
org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:318)
[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:131)
[JBossINF] at
org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:90)
[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:221)
[JBossINF] at
org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:201)
[JBossINF] at
org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
[JBossINF] at
org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
[JBossINF] at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
[JBossINF] at
org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
[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:192)
[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:759)
[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:1180)
[JBossINF] at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1728)
[JBossINF] at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1710)
[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]
[JBossINF]
{noformat}
...
{noformat}
[JBossINF] 17:02:40,549 ERROR [org.infinispan.transaction.tm.DummyTransaction]
(ajp-perf21-10.16.90.60-8009-104) ISPN000109: beforeCompletion() failed for
SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid{id=6307}, status=1},
lockedKeys=null, backupKeyLocks=null, viewId=8}
org.infinispan.transaction.synchronization.SyncLocalTransaction@189b}
org.infinispan.transaction.synchronization.SynchronizationAdapter@18ba:
org.infinispan.CacheException: Could not prepare.
[JBossINF] at
org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:70)
[JBossINF] at
org.infinispan.transaction.tm.DummyTransaction.notifyBeforeCompletion(DummyTransaction.java:230)
[JBossINF] at
org.infinispan.transaction.tm.DummyTransaction.runPrepare(DummyTransaction.java:241)
[JBossINF] at
org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:86)
[JBossINF] at
org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)
[JBossINF] at
org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
[JBossINF] at
org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1512)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:854)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
[jboss-as-web-7.1.2.Final-SNAPSHOT.jar:7.1.2.Final-SNAPSHOT]
[JBossINF] at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at
org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:445)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931)
[jbossweb-7.0.15.Final.jar:]
[JBossINF] at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30]
[JBossINF] Caused by: javax.transaction.xa.XAException
[JBossINF] at
org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:160)
[JBossINF] at
org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:122)
[JBossINF] at
org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:68)
[JBossINF] ... 21 more
{noformat}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: