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

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}