[jboss-jira] [JBoss JIRA] (AS7-4725) CLONE - Sessions lost on server crash when using DIST SYNC mode (Lock is being held by null)

Radoslav Husar created AS7-4725: ----------------------------------- Summary: CLONE - Sessions lost on server crash when using DIST SYNC mode (Lock is being held by null) Key: AS7-4725 URL: https://issues.jboss.org/browse/AS7-4725 Project: Application Server 7 Issue Type: Bug Components: Clustering Affects Versions: 7.1.1.Final Reporter: Radoslav Husar Assignee: Paul Ferraro Priority: Critical Fix For: 7.1.2.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: https://issues.jboss.org/secure/ContactAdministrators!default.jspa For more information on JIRA, see: http://www.atlassian.com/software/jira