jgroups.TimeoutException causes failure of prepare view and long time to form a cluster in startup
dex80526 Jun 1, 2012 1:50 PMI have 2 node cluster in replication mode using jgroup-tcp.xml config.
It has a cache loader configured with ~1/2 million entries in Berkley DB.
It will take a long 8 miuntes for second node to join the cluster. I saw lot exceptions in the logs.
What and where should I look to fix the problem?
On the joining node:
2012-06-01/09:57:22.210/MDT [OOB-3,null] WARN org.infinispan.statetransfer.BaseStateTransferManagerImpl[224] - ISPN000167: Rejecting state pushed by node portal2.performancetest.com-48158 for view 7, there is no state transfer in progress (we are at view 8)
2012-06-01/09:57:22.210/MDT [OOB-3,null] WARN org.infinispan.statetransfer.BaseStateTransferManagerImpl[224] - ISPN000167: Rejecting state pushed by node portal2.performancetest.com-48158 for view 7, there is no state transfer in progress (we are at view 8)
2012-06-01/09:57:27.271/MDT [OOB-2,null] WARN org.infinispan.statetransfer.BaseStateTransferManagerImpl[224] - ISPN000167: Rejecting state pushed by node portal2.performancetest.com-48158 for view 7, there is no state transfer in progress (we are at view 8)
2012-06-01/09:57:27.271/MDT [OOB-2,null] WARN org.infinispan.statetransfer.BaseStateTransferManagerImpl[224] - ISPN000167: Rejecting state pushed by node portal2.performancetest.com-48158 for view 7, there is no state transfer in progress (we are at view 8)
On the first node (coordinator):
2012-06-01/09:53:00.219/MDT [Incoming-1,null] INFO org.infinispan.remoting.transport.jgroups.JGroupsTransport[607] - ISPN000094: Received new cluster view: [portal2.performancetest.com-48158|3] [portal2.performancetest.com-48158, portal1.performancetest.com-840]
2012-06-01/09:53:24.324/MDT [OOB-2,null] WARN org.infinispan.commands.control.CacheViewControlCommand[141] - ISPN000071: Caught exception when handling command CacheViewControlCommand{cache=keychain, type=PREPARE_VIEW, sender=portal1.performancetest.com-42037, newViewId=4, newMembers=[portal2.performancetest.com-48158, portal1.performancetest.com-42037], oldViewId=3, oldMembers=[portal2.performancetest.com-48158]}
java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:262)
at java.util.concurrent.FutureTask.get(FutureTask.java:119)
at org.infinispan.util.concurrent.AggregatingNotifyingFutureBuilder.get(AggregatingNotifyingFutureBuilder.java:93)
at org.infinispan.statetransfer.BaseStateTransferTask.finishPushingState(BaseStateTransferTask.java:139)
at org.infinispan.statetransfer.ReplicatedStateTransferTask.doPerformStateTransfer(ReplicatedStateTransferTask.java:116)
at org.infinispan.statetransfer.BaseStateTransferTask.performStateTransfer(BaseStateTransferTask.java:93)
at org.infinispan.statetransfer.BaseStateTransferManagerImpl.prepareView(BaseStateTransferManagerImpl.java:331)
at org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:485)
at org.infinispan.commands.control.CacheViewControlCommand.perform(CacheViewControlCommand.java:126)
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:95)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:221)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:201)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
at org.jgroups.JChannel.up(JChannel.java:716)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
at org.jgroups.protocols.RSVP.up(RSVP.java:179)
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:889)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:759)
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:365)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:602)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
at org.jgroups.protocols.FD.up(FD.java:273)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
at org.jgroups.stack.Protocol.up(Protocol.java:363)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1180)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1728)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1710)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Caused by: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at org.infinispan.util.Util.rewrapAsCacheException(Util.java:525)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:172)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:489)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:161)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:183)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:240)
at org.infinispan.remoting.rpc.RpcManagerImpl.access$000(RpcManagerImpl.java:78)
at org.infinispan.remoting.rpc.RpcManagerImpl$1.call(RpcManagerImpl.java:274)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
... 3 more
Caused by: org.jgroups.TimeoutException: TimeoutException
at org.jgroups.util.Promise._getResultWithTimeout(Promise.java:82)
at org.jgroups.util.Promise.getResultWithTimeout(Promise.java:41)
at org.jgroups.util.AckCollector.waitForAllAcks(AckCollector.java:93)
at org.jgroups.protocols.RSVP$Entry.block(RSVP.java:275)
at org.jgroups.protocols.RSVP.down(RSVP.java:114)
at org.jgroups.stack.ProtocolStack.down(ProtocolStack.java:1033)
at org.jgroups.JChannel.down(JChannel.java:730)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.down(MessageDispatcher.java:559)
at org.jgroups.blocks.RequestCorrelator.sendUnicastRequest(RequestCorrelator.java:193)
at org.jgroups.blocks.UnicastRequest.sendRequest(UnicastRequest.java:44)
at org.jgroups.blocks.Request.execute(Request.java:83)
at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:342)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:270)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:165)
... 11 more
2012-06-01/09:53:24.324/MDT [OOB-2,null] WARN org.infinispan.commands.control.CacheViewControlCommand[141] - ISPN000071: Caught exception when handling command CacheViewControlCommand{cache=keychain, type=PREPARE_VIEW, sender=portal1.performancetest.com-42037, newViewId=4, newMembers=[portal2.performancetest.com-48158, portal1.performancetest.com-42037], oldViewId=3, oldMembers=[portal2.performancetest.com-48158]}
java.util.concurrent.ExecutionException: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:262)
at java.util.concurrent.FutureTask.get(FutureTask.java:119)
at org.infinispan.util.concurrent.AggregatingNotifyingFutureBuilder.get(AggregatingNotifyingFutureBuilder.java:93)
at org.infinispan.statetransfer.BaseStateTransferTask.finishPushingState(BaseStateTransferTask.java:139)
at org.infinispan.statetransfer.ReplicatedStateTransferTask.doPerformStateTransfer(ReplicatedStateTransferTask.java:116)
at org.infinispan.statetransfer.BaseStateTransferTask.performStateTransfer(BaseStateTransferTask.java:93)
at org.infinispan.statetransfer.BaseStateTransferManagerImpl.prepareView(BaseStateTransferManagerImpl.java:331)
at org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:485)
at org.infinispan.commands.control.CacheViewControlCommand.perform(CacheViewControlCommand.java:126)
at org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:95)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:221)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:201)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)
at org.jgroups.JChannel.up(JChannel.java:716)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)
at org.jgroups.protocols.RSVP.up(RSVP.java:179)
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:889)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)
at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:759)
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:365)
at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:602)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
at org.jgroups.protocols.FD.up(FD.java:273)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
at org.jgroups.stack.Protocol.up(Protocol.java:363)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1180)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1728)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1710)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Caused by: org.infinispan.CacheException: org.jgroups.TimeoutException: TimeoutException
at org.infinispan.util.Util.rewrapAsCacheException(Util.java:525)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:172)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:489)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:161)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:183)
at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:240)
at org.infinispan.remoting.rpc.RpcManagerImpl.access$000(RpcManagerImpl.java:78)
at org.infinispan.remoting.rpc.RpcManagerImpl$1.call(RpcManagerImpl.java:274)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
... 3 more
Caused by: org.jgroups.TimeoutException: TimeoutException
at org.jgroups.util.Promise._getResultWithTimeout(Promise.java:82)
at org.jgroups.util.Promise.getResultWithTimeout(Promise.java:41)
at org.jgroups.util.AckCollector.waitForAllAcks(AckCollector.java:93)
at org.jgroups.protocols.RSVP$Entry.block(RSVP.java:275)
at org.jgroups.protocols.RSVP.down(RSVP.java:114)
at org.jgroups.stack.ProtocolStack.down(ProtocolStack.java:1033)
at org.jgroups.JChannel.down(JChannel.java:730)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.down(MessageDispatcher.java:559)
at org.jgroups.blocks.RequestCorrelator.sendUnicastRequest(RequestCorrelator.java:193)
at org.jgroups.blocks.UnicastRequest.sendRequest(UnicastRequest.java:44)
at org.jgroups.blocks.Request.execute(Request.java:83)
at org.jgroups.blocks.MessageDispatcher.sendMessage(MessageDispatcher.java:342)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.processSingleCall(CommandAwareRpcDispatcher.java:270)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:165)
... 11 more