0 Replies Latest reply on Sep 12, 2012 2:42 AM by mperdikeas

    JBoss AS71.1.1 clustering "Could not commit" and "timeout sending message" exceptions

    mperdikeas Sep 12, 2012 2:42 AM

      We are launching two JBoss AS71.1.1 instances that form a cluster based on their multicast address. For this simple test, the two instances are launced on the same machine with port offsets like this:

       

      bin/standalone.sh -c standalone-ha.xml -b 172.31.129.29 -u 230.0.0.4 -Djboss.server.base.dir=standalone-node1 -Djboss.node.name=node1 -Djboss.socket.binding.port-offset=100

       

      - and -

       

      bin/standalone.sh -c standalone-ha.xml -b 172.31.129.29 -u 230.0.0.4 -Djboss.server.base.dir=standalone-node2 -Djboss.node.name=node2 -Djboss.socket.binding.port-offset=200

       

      The two servers are fronted by an nginx server that dispatches in a round-robin fashion to one or the other. We have also deployed the same, simple, web application (an EAR) on both servers. No database access or anything is involved. The EAR is a dead-simple app that collects some String objects typed-in by the user in a session-scoped backing bean.

       

      We are then using a script that alternately kills one or the other instance in the cluster and re-launches them, giving them time to syncrhonize before the next kill. When accessing the application we are then seeing the following exceptions. The exceptions occur every time after a few kills and re-launches of the servers.

       

      1. ERROR [org.infinispan.transaction.TransactionCoordinator] (http--172.31.129.29-8180-1) ISPN000097: Error while processing 1PC PrepareCommand: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to node2/web  - see full trace below
      2. ERROR [org.infinispan.transaction.tm.DummyTransaction] (http--172.31.129.29-8180-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid{id=59}, status=3}, lockedKeys=null, backupKeyLocks=null, viewId=3} org.infinispan.transaction.synchronization.SyncLocalTransaction@39} org.infinispan.transaction.synchronization.SynchronizationAdapter@58: org.infinispan.CacheException: Could not commit. - see full trace below

       

      === FULL TRACE OF ERROR 1 ===

      09:12:08,627 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (http--172.31.129.29-8180-1) ISPN000136: Execution error: org.infinispan.CacheException: org.jgroups.TimeoutException: timeout sending message to node2/web
      at org.infinispan.util.Util.rewrapAsCacheException(Util.java:524) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:168) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:478) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:148) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:169) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:219) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:206) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:201) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:184) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.ReplicationInterceptor.broadcastPrepare(ReplicationInterceptor.java:136) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.ReplicationInterceptor.visitPrepareCommand(ReplicationInterceptor.java:128) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.EntryWrappingInterceptor.visitPrepareCommand(EntryWrappingInterceptor.java:80) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.invokeNextAndCommitIf1Pc(AbstractTxLockingInterceptor.java:120) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:105) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:58) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:106) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.StateTransferLockInterceptor.handleWithRetries(StateTransferLockInterceptor.java:207) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.StateTransferLockInterceptor.visitPrepareCommand(StateTransferLockInterceptor.java:84) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:89) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:86) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:130) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.jboss.as.clustering.infinispan.DefaultEmbeddedCacheManager$ClassLoaderAwareCommandInterceptor.handleDefault(DefaultEmbeddedCacheManager.java:410) [jboss-as-clustering-infinispan-7.1.1.Final.jar:7.1.1.Final]
      at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:113) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:131) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:345) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:174) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.tm.DummyTransaction.notifyAfterCompletion(DummyTransaction.java:272) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:321) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:90) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:100) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75) [jboss-as-clustering-web-spi-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1530)
      at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:865)
      at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47)
      at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133)
      at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91)
      at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88)
      at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56)
      at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671)
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930)
      at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_03]
      Caused by: org.jgroups.TimeoutException: timeout sending message to node2/web
      at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:360) [jgroups-3.0.6.Final.jar:3.0.6.Final]
      at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:263) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:163) [infinispan-core-5.1.2.FINAL.jar:5.1.2.FINAL]
      ... 85 more

       

      === FULL TRACE OF ERROR 2 ===

      09:12:08,688 ERROR [org.infinispan.transaction.tm.DummyTransaction] (http--172.31.129.29-8180-1) ISPN000111: afterCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=DummyTransaction{xid=DummyXid{id=59}, status=3}, lockedKeys=null, backupKeyLocks=null, viewId=3} org.infinispan.transaction.synchronization.SyncLocalTransaction@39} org.infinispan.transaction.synchronization.SynchronizationAdapter@58: 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:272)
      at org.infinispan.transaction.tm.DummyTransaction.runCommitTx(DummyTransaction.java:321)
      at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:90)
      at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:100)
      at org.jboss.as.clustering.web.impl.TransactionBatchingManager.endBatch(TransactionBatchingManager.java:75)
      at org.jboss.as.web.session.DistributableSessionManager.processSessionRepl(DistributableSessionManager.java:1530) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.DistributableSessionManager.storeSession(DistributableSessionManager.java:865) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:47) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:133) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.JvmRouteValve.invoke(JvmRouteValve.java:88) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.session.LockingValve.invoke(LockingValve.java:56) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.13.Final.jar:]
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.13.Final.jar:]
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.13.Final.jar:]
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.13.Final.jar:]
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.13.Final.jar:]
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.13.Final.jar:]
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]
      at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_03]
      Caused by: javax.transaction.xa.XAException
      at org.infinispan.transaction.TransactionCoordinator.handleCommitFailure(TransactionCoordinator.java:219)
      at org.infinispan.transaction.TransactionCoordinator.commit(TransactionCoordinator.java:176)
      at org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:81)
      ... 21 more