Heartbeat issue with Topic

[andysCaplin]

C++ compiler version: g++ (GCC) 8.3.1 20190311 (Red Hat 8.3.1-3)
Hazelcast Cpp client version: 4.0.1
Hazelcast server version: 4.0
Number of the clients: 8
Cluster size, i.e. the number of Hazelcast cluster members: 9
OS version (Windows/Linux/OSX): Linux

Please attach relevant logs and files for client and server side.
Server side log

2021-06-10 16:47:57.783  INFO 7057 --- [ached.thread-13] c.h.internal.nio.tcp.TcpIpConnection     : [172.20.0.239]:5701 [dev] [4.0.3] Connection[id=8, /127.0.0.1:5701->/127.0.0.1:60152, qualifier=null, endpoint=[127.0.0.1]:60152, alive=false, connectionType=CPP] closed. Reason: Client heartbeat is timed out, closing connection to Connection[id=8, /127.0.0.1:5701->/127.0.0.1:60152, qualifier=null, endpoint=[127.0.0.1]:60152, alive=true, connectionType=CPP]. Now: 2021-06-10 16:47:57.782. LastTimePacketReceived: 2021-06-10 16:47:26.273
2021-06-10 16:47:57.786  INFO 7057 --- [_hopper.event-1] c.c.d.a.ClientCleanupService             : Client <11f1dccf-6aa7-493f-a21b-b95b548a9b06> has connected: ClientEvent{uuid='11f1dccf-6aa7-493f-a21b-b95b548a9b06', eventType=CONNECTED, address=/172.20.0.239:35984, clientType=CPP, name='hz.client_1', attributes=[]}
2021-06-10 16:47:57.786  INFO 7057 --- [ration.thread-1] c.h.c.i.p.t.AuthenticationMessageTask    : [172.20.0.239]:5701 [dev] [4.0.3] Received auth from Connection[id=10, /172.20.0.239:5701->/172.20.0.239:35984, qualifier=null, endpoint=[172.20.0.239]:35984, alive=true, connectionType=CPP], successfully authenticated, clientUuid: 11f1dccf-6aa7-493f-a21b-b95b548a9b06, client version: 4.0.1
2021-06-10 16:47:57.788  INFO 7057 --- [_hopper.event-3] c.h.client.impl.ClientEndpointManager    : [172.20.0.239]:5701 [dev] [4.0.3] Destroying ClientEndpoint{connection=Connection[id=8, /127.0.0.1:5701->/127.0.0.1:60152, qualifier=null, endpoint=[127.0.0.1]:60152, alive=false, connectionType=CPP], clientUuid='11f1dccf-6aa7-493f-a21b-b95b548a9b06, authenticated=true, clientVersion=4.0.1, creationTime=1623340045794, latest clientAttributes=null}
2021-06-10 16:47:57.788  INFO 7057 --- [_hopper.event-1] c.c.d.a.ClientCleanupService             : Client <11f1dccf-6aa7-493f-a21b-b95b548a9b06> has disconnected: ClientEvent{uuid='11f1dccf-6aa7-493f-a21b-b95b548a9b06', eventType=DISCONNECTED, address=/127.0.0.1:60152, clientType=CPP, name='hz.client_1', attributes=[]}
2021-06-10 16:47:57.788  INFO 7057 --- [pool-2-thread-2] c.c.datasource.licence.LicenceService    : Server Licence request: ServerRequest{peerUUID='11f1dccf-6aa7-493f-a21b-b95b548a9b06', requestType='License', productName='transformer', timestamp='1623340077', metaData={label=Transformer-2}}
2021-06-10 16:47:57.788  INFO 7057 --- [_hopper.event-1] c.c.d.a.ClientCleanupService             : Check remove peer <11f1dccf-6aa7-493f-a21b-b95b548a9b06> port 60152 ports [35984]

The client side logs the disconnect initiated by the server

Expected behaviour

Heartbeats should not stop being sent from the clients

Actual behaviour

Heartbeats not being sent when Topic code is in use

Steps to reproduce the behaviour

I've added a basic pub/sub Topic feature to 3 of the clients based on the example code.
The 1st of the 3 clients that comes up never has an issue.
The 1st client publishes an initial info message and then regular updates to the topic
The 2nd and 3rd of the clients subscribe to the topic and only publish the initial info message
The 2nd and 3rd of the clients disconnect from the server every 40 seconds
The thread that handles the updates on the 2nd and 3rd clients works fine. It receives and handles the updates as they arrive i.e. they're not stuck.

The server configuration is

<properties>
    <property name="hazelcast.heartbeat.failuredetector.type">deadline</property>
    <property name="hazelcast.heartbeat.interval.seconds">5</property>
    <property name="hazelcast.max.no.heartbeat.seconds">30</property>
    <property name="hazelcast.client.heartbeat.interval">5000</property>
    <property name="hazelcast.client.heartbeat.timeout">30000</property>
    <property name="hazelcast.client.max.no.heartbeat.seconds">30</property>
</properties>

The pub/sub code is

Subscribe

    try {
        static auto topic = hz_ptr->get_topic(topicname).get();
        static hazelcast::client::topic::listener topicListener;
        topicListener.
                on_received([](hazelcast::client::topic::message &&message) {
                    auto clusterMsg = message.get_message_object().get<CaplinCluster>().value();
                    if ( uuid.compare(clusterMsg.i_uuid) != 0 ) {
                        ds_msg_t *msg = (ds_msg_t *)calloc(1, sizeof(*msg));
                        msg->type = clusterMsg.i_type;
                        msg->len  = clusterMsg.i_len;
                        msg->msg  = clusterMsg.i_msg;
                        cluster_cb(clusterMsg.i_label.c_str(), msg);
                    } 
                });
        topic->add_message_listener(std::move(topicListener)).get();
    } catch (hazelcast::client::exception::iexception &e) {
        ds_log(event_log, DS_LOG_ERROR, "Discovery: Cluster - Failed to subscribe to <%s>\n", topicname);
    }

Publish

    try {
        CaplinCluster discoveryMsg = CaplinCluster{uuid, _ds_datasrc_local_label(), (int32_t)msg->type, (int32_t)msg->len, msg->msg};
        auto topic = hz_ptr->get_topic(topicname).get();
        topic->publish(discoveryMsg).get();
    } catch (hazelcast::client::exception::iexception &e) {
        ds_log(event_log, DS_LOG_ERROR, "Discovery: Cluster - Failed publish to <%s>\n", topicname);
    }

[yemreinci]

Hello @andysCaplin,

Thank you reporting this issue. I was able to reproduce it with a much simpler 1 subscriber / 1 publisher setup:

publisher.cpp:

#include <hazelcast/client/hazelcast_client.h>

int main()
{
    auto cli = hazelcast::new_client().get();

    auto topic = cli.get_topic("topic").get();

    for (int i = 1; i <= 100 ; ++i) {
        topic->publish<std::string>("some message " + std::to_string(i)).get();
        std::this_thread::sleep_for(std::chrono::seconds(1));
    }
}

subscriber.cpp:

#include <hazelcast/client/hazelcast_client.h>

int main()
{
    auto cli = hazelcast::new_client().get();
    auto topic = cli.get_topic("topic").get();

    hazelcast::client::topic::listener listener;
    listener.on_received([](hazelcast::client::topic::message &&msg) {
        std::cout << msg.get_message_object().get<std::string>() << std::endl;
    });

    topic->add_message_listener(std::move(listener));

    std::this_thread::sleep_for(std::chrono::seconds(9999));
}

And a single member configured as provided:

<properties>
    <property name="hazelcast.heartbeat.failuredetector.type">deadline</property>
    <property name="hazelcast.heartbeat.interval.seconds">5</property>
    <property name="hazelcast.max.no.heartbeat.seconds">30</property>
    <property name="hazelcast.client.heartbeat.interval">5000</property>
    <property name="hazelcast.client.heartbeat.timeout">30000</property>
    <property name="hazelcast.client.max.no.heartbeat.seconds">30</property>
</properties>

As reported, member closes the connection to the subscriber client after about 30 seconds:

INFO: [192.168.1.57]:5701 [dev] [4.2] Connection[id=2, /127.0.0.1:5701->/127.0.0.1:38508, qualifier=null, endpoint=[127.0.0.1]:38508, alive=false, connectionType=CPP, planeIndex=-1] closed. Reason: Client heartbeat is timed out, closing connection to Connection[id=2, /127.0.0.1:5701->/127.0.0.1:38508, qualifier=null, endpoint=[127.0.0.1]:38508, alive=true, connectionType=CPP, planeIndex=-1]. Now: 2021-06-21 18:55:15.263. LastTimePacketReceived: 2021-06-21 18:54:39.441

[andysCaplin]

Thanks for raising the issue. Do you have a rough timescale for when 4.1.2 might be available.
Also, is there any work-around I can use to avoid the issue.
We want to use Topics for a new feature but we can't until this issue is fixed.

[ihsandemir]

Hello @andycCaplin Just talked to the product management and we will do a release for this fix.

Meanwhile, here is an ugly workaround to avoid the problem. You can just have a thread which executes the following every second to do a dummy get from a map, e.g.

cli->get_map("dummy_map").get()->get<int, int>(rand());

This will trigger an update every second so that the server will not close the connection. This can be a low priority thread.

[ihsandemir]

@andysCaplin I submitted the fix PR. Can you review and test it from the PR branch?

[andysCaplin]

@ihsandemir Hi - I'll test that tomorrow. Also - in the last read / last write time area - I got an odd log from the library with a negative millisecond timestamp - see "lastReadTime=2021-06-23 15:35:58.-67" in the log below.

2021/06/23-15:35:58.768856 +0000: (90): INFO: Discovery: Library - <hz.client_1><soaktest> ClientConnection{alive=0, connectionId=5, remoteEndpoint=Address[10.42.4.229:5701], lastReadTime=2021-06-23 15:35:58.-67, closedTime=2021-06-23 15:35:58.000, connected server version=4.0.3} closed. Reason: Socket read error. asio.misc:2 for ClientConnection{alive=1, connectionId=5, remoteEndpoint=Address[10.42.4.229:5701], lastReadTime=2021-06-23 15:35:58.-67, closedTime=never, connected server version=4.0.3}
.0.3}

[ihsandemir]

@ihsandemir Hi - I'll test that tomorrow. Also - in the last read / last write time area - I got an odd log from the library with a negative millisecond timestamp - see "lastReadTime=2021-06-23 15:35:58.-67" in the log below.

2021/06/23-15:35:58.768856 +0000: (90): INFO: Discovery: Library - <hz.client_1><soaktest> ClientConnection{alive=0, connectionId=5, remoteEndpoint=Address[10.42.4.229:5701], lastReadTime=2021-06-23 15:35:58.-67, closedTime=2021-06-23 15:35:58.000, connected server version=4.0.3} closed. Reason: Socket read error. asio.misc:2 for ClientConnection{alive=1, connectionId=5, remoteEndpoint=Address[10.42.4.229:5701], lastReadTime=2021-06-23 15:35:58.-67, closedTime=never, connected server version=4.0.3}
.0.3}

Thanks for this feedback. I opened another issue for fixing these times.

[ihsandemir]

Hello @andysCaplin I also sent another PR which fixes the printing of msecs part in the logs correctly.

Did you get a chance to try the actual fix yet? Let me know so that I can merge the fix PR. Thanks.

[andysCaplin]

Hi - yes I did. I added a comment in the wrong place (#892) - sorry. Copying here with a question I added

@ihsandemir I rebuilt my application with the new library and I'm not getting the disconnects any more.

Could I ask you a question about client-server interaction ?

We have a setup where we have multiple servers ( Java 4.0 ) and one client. ( C++ 4.0 ) Say Server1, Server2, Server3 and Client1
Everything is started and connected.

If we break the network connection between Server1 and Client1 we get what looks like inconsistent behaviour

Client1 sees a socket error but does not get a CLIENT_DISCONNECTED lifecycle event - which seems correct because we have other servers available
Server1 gets a CLIENT_DISCONNECTED lifecycle event for the Client1
If we stop Server2 and Server3 then Client1 will get a CLIENT_DISCONNECTED lifecycle event.
Is that correct ?
And if so, how do we distinguish at the server level the difference between a client disconnecting from a server and if we stop it completely ?
Do we need to have some reference counting scheme at the server ?