Replication Timeout just after restarting hotrod server modules
boudhomme May 24, 2011 9:35 AMHi,
I'm testing Infinispan (4.2.1 FINAL) with 3 hotrod server modules, but I get randomly "Replication Timeout" just after restarting modules with a cleaned cacheStore (CTRL-C ; rm -rf /FileCacheStoreLocation/* then startserver.sh -c .... on each server). I also noticed that this error occurs when the cache was heavy loaded.
Why I'm getting "Replication Timeout" even though the cache is clean (no entry in the cache) and the modules just restarted ?
The log from one node :
2011-05-24 11:07:44,460 INFO [org.infinispan.server.core.Main$] (main) Start main with args: -l, 10.50.1.60, -r, hotrod, -c, ../etc/qualif.xml 2011-05-24 11:07:46,097 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Starting JGroups Channel 2011-05-24 11:07:46,098 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Unable to use any JGroups configuration mechanisms provided in properties {}. Using default JGroups configuration! 2011-05-24 11:07:50,050 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Received new cluster view: [NB01VMLX-8734|0] [NB01VMLX-8734] 2011-05-24 11:07:50,064 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (InfinispanServer-Main) Cache local address is NB01VMLX-8734, physical addresses are [10.50.1.60:39637] 2011-05-24 11:07:50,152 INFO [org.infinispan.loaders.decorators.AsyncStore] (InfinispanServer-Main) Async cache loader starting org.infinispan.loaders.decorators.AsyncStore@51017ca1 2011-05-24 11:07:50,270 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-1,NB01VMLX-8734) Received new cluster view: [NB01VMLX-8734|1] [NB01VMLX-8734, NB02VMLX-28677] 2011-05-24 11:07:50,436 INFO [org.infinispan.loaders.decorators.AsyncStore] (InfinispanServer-Main) Async cache loader starting org.infinispan.loaders.decorators.AsyncStore@76d78df0 2011-05-24 11:07:50,518 INFO [org.infinispan.remoting.rpc.RpcManagerImpl] (InfinispanServer-Main) Trying to fetch state from NB02VMLX-28677 2011-05-24 11:07:50,528 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-2,NB01VMLX-8734) Received new cluster view: [NB01VMLX-8734|2] [NB01VMLX-8734, NB02VMLX-28677, NB03VMLX-19057] 2011-05-24 11:07:50,528 INFO [org.infinispan.distribution.DistributionManagerImpl] (Incoming-2,NB01VMLX-8734) Detected a view change. Member list changed from [NB01VMLX-8734, NB02VMLX-28677] to [NB01VMLX-8734, NB02VMLX-28677, NB03VMLX-19057] 2011-05-24 11:07:50,528 INFO [org.infinispan.distribution.DistributionManagerImpl] (Incoming-2,NB01VMLX-8734) This is a JOIN event! Wait for notification from new joiner NB03VMLX-19057 2011-05-24 11:07:50,635 INFO [org.infinispan.remoting.rpc.RpcManagerImpl] (InfinispanServer-Main) Successfully retrieved and applied state from NB02VMLX-28677 2011-05-24 11:08:00,790 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (InfinispanServer-Main) Execution error: org.infinispan.util.concurrent.TimeoutException: Replication timeout for NB02VMLX-28677 at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:49) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:419) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:102) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:126) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:231) at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:218) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:201) at org.infinispan.remoting.rpc.RpcManagerImpl.broadcastRpcCommand(RpcManagerImpl.java:194) at org.infinispan.interceptors.ReplicationInterceptor.handleCrudMethod(ReplicationInterceptor.java:115) at org.infinispan.interceptors.ReplicationInterceptor.visitPutKeyValueCommand(ReplicationInterceptor.java:78) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:297) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.CacheStoreInterceptor.visitPutKeyValueCommand(CacheStoreInterceptor.java:203) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.CacheLoaderInterceptor.visitPutKeyValueCommand(CacheLoaderInterceptor.java:81) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:184) at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:113) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) at org.infinispan.interceptors.IsMarshallableInterceptor.visitPutKeyValueCommand(IsMarshallableInterceptor.java:86) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:95) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:62) at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:58) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:80) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:273) at org.infinispan.CacheDelegate.putIfAbsent(CacheDelegate.java:459) at org.infinispan.CacheSupport.putIfAbsent(CacheSupport.java:40) at org.infinispan.server.hotrod.HotRodServer$$anonfun$1.apply(HotRodServer.scala:88) at org.infinispan.server.hotrod.HotRodServer$$anonfun$1.apply(HotRodServer.scala:78) at org.infinispan.server.hotrod.HotRodServer.isViewUpdated(HotRodServer.scala:105) at org.infinispan.server.hotrod.HotRodServer.org$infinispan$server$hotrod$HotRodServer$$updateTopologyView(HotRodServer.scala:100) at org.infinispan.server.hotrod.HotRodServer.addSelfToTopologyView(HotRodServer.scala:78) at org.infinispan.server.hotrod.HotRodServer.startTransport(HotRodServer.scala:66) at org.infinispan.server.core.AbstractProtocolServer.start(AbstractProtocolServer.scala:70) at org.infinispan.server.hotrod.HotRodServer.start(HotRodServer.scala:48) at org.infinispan.server.core.Main$.boot(Main.scala:114) at org.infinispan.server.core.Main$$anon$1.call(Main.scala:68) at org.infinispan.server.core.Main$$anon$1.call(Main.scala:65) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) 2011-05-24 11:09:27,807 INFO [org.infinispan.server.core.ShutdownHook] (ShutdownHookThread) Posting Shutdown Request to the server... 2011-05-24 11:09:27,887 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (StopThread) Disconnecting and closing JGroups Channel 2011-05-24 11:09:28,265 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (StopThread) Stopping the RpcDispatcher
The configuration file used by all nodes :
<?xml version="1.0" encoding="UTF-8"?> <infinispan xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:infinispan:config:4.2 http://www.infinispan.org/schemas/infinispan-config-4.2.xsd" xmlns="urn:infinispan:config:4.2"> <global> <transport clusterName="qualif"/> <globalJmxStatistics enabled="true"/> </global> <default> <jmxStatistics enabled="true"/> <clustering mode="distribution"> <l1 enabled="true" lifespan="60000"/> <hash numOwners="2" /> <sync replTimeout="20000"/> </clustering> <loaders preload="true" shared="true"> <loader class="org.infinispan.loaders.file.FileCacheStore"> <async enabled="true" /> <properties> <property name="location" value="/mnt/nas" /> </properties> </loader> </loaders> </default> </infinispan>
And the bandwidth between nodes is 2GBps.
Thanks !