Hazelcast client disconnecting from cluster with heartbeat problems

[wneild]

I'm using Hazelcast 3.7 and have experienced the Java Client disconnecting from the cluster unprovoked.

Below is the log output from a client that disconnected during an occurrence of this issue:

2016-09-21 14:02:01.885 [hz.client_0.internal-3] WARN  c.h.c.c.ClientConnectionManager - hz.client_0 [cluster-name] [3.7] Heartbeat failed to connection : ClientConnection{live=true, connectionId=1, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[connected local=/0.0.0.0:48980 remote=/0.0.0.0:5701]}, remoteEndpoint=[0.0.0.0]:5701, lastReadTime=2016-09-21 14:02:01.882, lastWriteTime=2016-09-21 14:02:01.875, closedTime=never, lastHeartbeatRequested=2016-09-21 06:40:13.901, lastHeartbeatReceived=2016-09-21 06:40:13.901}
2016-09-21 14:02:01.909 [hz.client_0.internal-1] WARN  c.h.c.spi.ClientPartitionService - hz.client_0 [cluster-name] [3.7] Error while fetching cluster partition table!
java.util.concurrent.ExecutionException: com.hazelcast.spi.exception.TargetDisconnectedException: Disconnecting from member [0.0.0.0]:5701 due to heartbeat problems. Current time: 2016-09-21 14:02:01.908. Last heartbeat requested: 2016-09-21 06:40:13.901. Last heartbeat received: 2016-09-21 06:40:13.901. Last read: 2016-09-21 14:02:01.898. Connection ClientConnection{live=true, connectionId=1, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[connected local=/0.0.0.0:48980 remote=/0.0.0.0:5701]}, remoteEndpoint=[0.0.0.0]:5701, lastReadTime=2016-09-21 14:02:01.894, lastWriteTime=2016-09-21 14:02:01.875, closedTime=never, lastHeartbeatRequested=2016-09-21 06:40:13.901, lastHeartbeatReceived=2016-09-21 06:40:13.901}
        at com.hazelcast.client.spi.impl.ClientInvocationFuture.resolve(ClientInvocationFuture.java:66) ~[hazelcast-all-3.7.jar:3.7]
        at com.hazelcast.spi.impl.AbstractInvocationFuture$1.run(AbstractInvocationFuture.java:246) ~[hazelcast-all-3.7.jar:3.7]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_91]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
        at com.hazelcast.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-all-3.7.jar:3.7]
        at com.hazelcast.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:92) [hazelcast-all-3.7.jar:3.7]
Caused by: com.hazelcast.spi.exception.TargetDisconnectedException: Disconnecting from member [0.0.0.0]:5701 due to heartbeat problems. Current time: 2016-09-21 14:02:01.908. Last heartbeat requested: 2016-09-21 06:40:13.901. Last heartbeat received: 2016-09-21 06:40:13.901. Last read: 2016-09-21 14:02:01.898. Connection ClientConnection{live=true, connectionId=1, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[connected local=/0.0.0.0:48980 remote=/0.0.0.0:5701]}, remoteEndpoint=[0.0.0.0]:5701, lastReadTime=2016-09-21 14:02:01.894, lastWriteTime=2016-09-21 14:02:01.875, closedTime=never, lastHeartbeatRequested=2016-09-21 06:40:13.901, lastHeartbeatReceived=2016-09-21 06:40:13.901}
        at com.hazelcast.spi.exception.TargetDisconnectedException.newTargetDisconnectedExceptionCausedByHeartbeat(TargetDisconnectedException.java:66) ~[hazelcast-all-3.7.jar:3.7]
        at com.hazelcast.client.spi.impl.ClientInvocationServiceSupport$CleanResourcesTask.run(ClientInvocationServiceSupport.java:221) ~[hazelcast-all-3.7.jar:3.7]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_91]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_91]
        ... 5 common frames omitted
2016-09-21 14:02:01.942 [hz.client_0.internal-3] WARN  c.h.c.c.nio.ClientConnection - hz.client_0 [cluster-name] [3.7] Connection [/0.0.0.0:5701] lost. Reason: com.hazelcast.spi.exception.TargetDisconnectedException[Disconnecting from member [0.0.0.0]:5701 due to heartbeat problems. Current time: 2016-09-21 14:02:01.908. Last heartbeat requested: 2016-09-21 06:40:13.901. Last heartbeat received: 2016-09-21 06:40:13.901. Last read: 2016-09-21 14:02:01.882. Connection ClientConnection{live=true, connectionId=1, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[connected local=/0.0.0.0:48980 remote=/0.0.0.0:5701]}, remoteEndpoint=[0.0.0.0]:5701, lastReadTime=2016-09-21 14:02:01.882, lastWriteTime=2016-09-21 14:02:01.875, closedTime=never, lastHeartbeatRequested=2016-09-21 06:40:13.901, lastHeartbeatReceived=2016-09-21 06:40:13.901}]
2016-09-21 14:02:01.960 [hz.client_0.internal-3] WARN  c.h.c.c.ClientConnectionManager - hz.client_0 [cluster-name] [3.7] Heartbeat is back to healthy for connection : ClientConnection{live=false, connectionId=1, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[closed]}, remoteEndpoint=[0.0.0.0]:5701, lastReadTime=2016-09-21 14:02:01.908, lastWriteTime=2016-09-21 14:02:01.875, closedTime=2016-09-21 14:02:01.908, lastHeartbeatRequested=2016-09-21 06:40:13.901, lastHeartbeatReceived=2016-09-21 06:40:13.901}
2016-09-21 14:02:01.962 [hz.client_0.user-8] INFO  com.hazelcast.core.LifecycleService - hz.client_0 [cluster-name] [3.7] HazelcastClient 3.7 (20160817 - 1302600) is CLIENT_DISCONNECTED
2016-09-21 14:02:01.963 [hz.client_0.thread-in] WARN  c.h.c.c.nio.ClientConnection - hz.client_0 [cluster-name] [3.7] Connection [/1.1.1.1:5701] lost. Reason: java.io.EOFException[Remote socket closed!]
2016-09-21 14:02:01.963 [hz.client_0.internal-3] WARN  c.h.c.c.ClientConnectionManager - hz.client_0 [cluster-name] [3.7] Heartbeat is back to healthy for connection : ClientConnection{live=false, connectionId=2, socketChannel=DefaultSocketChannelWrapper{socketChannel=java.nio.channels.SocketChannel[closed]}, remoteEndpoint=[1.1.1.1]:5701, lastReadTime=2016-09-21 14:02:01.953, lastWriteTime=2016-09-21 13:46:21.272, closedTime=2016-09-21 14:02:01.953, lastHeartbeatRequested=2016-09-21 08:29:58.901, lastHeartbeatReceived=2016-09-21 08:29:58.902}

[sancar]

Hi @wneild
Can we describe how the issue appeared ?
What can we try to reproduce the issue ?

[wneild]

@sancar I couldn't reproduce it reliably at the time but we have since upgraded to 3.7.3 and have not seen a re-occurrence of this issue. On that basis, I'll close this issue.