0 Replies Latest reply on Mar 1, 2015 3:43 PM by frank_s

Infinispan HotRod server stuck under heavy connect load, not servicing requests

frank_s Mar 1, 2015 3:43 PM

I am working on a product that has many applications running on several servers. They share caches using a cluster of 6 stand-alone Infinispan servers. The applications access the cache using a java HotRod RemoteCacheManager.

We have been performing some resilience tests and managed to render more than one Infinispan server inoperable. It will accept new HotRod connections, but will not service them. This is causing the clients to time out and disconnect, then reconnect, over and over again, the net result being a ton of CLOSE_WAIT connections. When the TCP connections are checked using a tool like netstat, we can see that there is data on the receive queue for the HotRod server port (11222) that is never drained. Since these sockets are never read, they stay in this half-open CLOSE_WAIT state indefinitely.

To double check the server’s responsiveness, I telnet to port 11222 and enter some nonsense. Normally the server would send back an error message, but when in this bad state, it doesn’t respond at all.

Before I describe the situation in more detail, here is some information about our setup:

Infinispan server version 7.1.1. Also tested 7.0.2 and witnessed the same behavior.
6 servers, distributed caches, 2 owners.

I have attached a copy of our clustered.xml file. There is also a stack trace attached (more on that later).

The test we have been performing is to isolate one of the servers as if there was a network outage. The isolated server hosts some of our applications and one of the Infinispan servers. We have been using iptables to drop all traffic, with the exception of ssh so we can still observe it. We use these iptables commands:

iptables -F

iptables -X

iptables -P INPUT DROP

iptables -P OUTPUT DROP

iptables -P FORWARD DROP

iptables -A INPUT -i lo -j ACCEPT

iptables -A OUTPUT -o lo -j ACCEPT

iptables -A INPUT -p tcp --dport 22 -m state --state NEW,ESTABLISHED -j ACCEPT

iptables -A OUTPUT -p tcp --sport 22 --dport 513:65535 -m state --state ESTABLISHED -j ACCEPT

iptables -A INPUT -j DROP

iptables -A OUTPUT -j DROP

When the testing begins, we see some error messages in the log. I believe that these are expected given the nature of our test:

ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (remote-thread--p3-t187) ISPN000136: Execution error: org.infinispan.remoting.transport.jgroups.SuspectException: One or more nodes have left the cluster while replicating command SingleRpcCommand{cacheName='cacheTest', command=PutKeyValueCommand{key=[B0x033e1f6d6f6e6974..[34], value=[B0x034c0000014bc2c4..[10], flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedLifespanExpirableMetadata{lifespan=86400000, version=NumericVersion{version=17732932122709415}}, successful=true}}

at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:533) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:283) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.handleNonTxWriteCommand(BaseDistributionInterceptor.java:236) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.distribution.NonTxDistributionInterceptor.visitPutKeyValueCommand(NonTxDistributionInterceptor.java:93) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:386) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.EntryWrappingInterceptor.setSkipRemoteGetsAndInvokeNextForDataCommand(EntryWrappingInterceptor.java:474) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.EntryWrappingInterceptor.visitPutKeyValueCommand(EntryWrappingInterceptor.java:187) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitPutKeyValueCommand(AbstractLockingInterceptor.java:48) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:35) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.statetransfer.StateTransferInterceptor.handleNonTxWriteCommand(StateTransferInterceptor.java:179) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.statetransfer.StateTransferInterceptor.visitPutKeyValueCommand(StateTransferInterceptor.java:108) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:159) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:145) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:35) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:71) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.remote.BaseRpcInvokingCommand.processVisitableCommand(BaseRpcInvokingCommand.java:39) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.commands.remote.SingleRpcCommand.perform(SingleRpcCommand.java:48) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.remoting.inboundhandler.BasePerCacheInboundInvocationHandler.invokePerform(BasePerCacheInboundInvocationHandler.java:84) [infinispan-core.jar:7.1.1.Final]

at org.infinispan.remoting.inboundhandler.BaseBlockingRunnable.run(BaseBlockingRunnable.java:31) [infinispan-core.jar:7.1.1.Final]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_51]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_51]

at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51]

02-25 17:04:21,106 WARN [org.infinispan.remoting.inboundhandler.NonTotalOrderPerCacheInboundInvocationHandler] (remote-thread--p3-t187) ISPN000071: Caught exception when handling command SingleRpcCommand{cacheName='cacheTest', command=PutKeyValueCommand{key=[B0x033e1f6d6f6e6974..[34], value=[B0x034c0000014bc2c4..[10], flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedLifespanExpirableMetadata{lifespan=86400000, version=NumericVersion{version=17732932122709415}}, successful=true}}: org.infinispan.remoting.transport.jgroups.SuspectException: One or more nodes have left the cluster while replicating command SingleRpcCommand{cacheName='cacheTest', command=PutKeyValueCommand{key=[B0x033e1f6d6f6e6974..[34], value=[B0x034c0000014bc2c4..[10], flags=[IGNORE_RETURN_VALUES], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedLifespanExpirableMetadata{lifespan=86400000, version=NumericVersion{version=17732932122709415}}, successful=true}}