C++ client crashes when server doesn't respond to HB

[siwhiting]

Suspect that this is same issue as reported in #428. Just reproduced in a different manner.

hazelcast java server 3.8.2 running java8 on centos-6 on machine1
hazelcast C++ client 3.10-BETA-1 running on centos-6 / 32 bit on machine2.

After client successfully establishes connection to server. Use gdb to attach to sever pid (don't continue process) so that server doesn't respond to client.

After approx 1 min, the following core stack trace is seen:

(gdb) bt
#0 0x00cac430 in __kernel_vsyscall ()
#1 0x025b6781 in raise () from /lib/libc.so.6
#2 0x025b805a in abort () from /lib/libc.so.6
#3 0x008d5b87 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/libstdc++.so.6
#4 0x008d39e6 in ?? () from /usr/lib/libstdc++.so.6
#5 0x008d3a23 in std::terminate() () from /usr/lib/libstdc++.so.6
#6 0x008d3b6b in __cxa_throw () from /usr/lib/libstdc++.so.6
#7 0x00874960 in std::__throw_length_error(char const*) () from /usr/lib/libstdc++.so.6
#8 0x008b0ef6 in std::basic_string<char, std::char_traits, std::allocator >::_Rep::_S_create(unsigned int, unsigned int, std::allocator const&) ()
from /usr/lib/libstdc++.so.6
#9 0x008b2029 in std::basic_string<char, std::char_traits, std::allocator >::_Rep::_M_clone(std::allocator const&, unsigned int) ()
from /usr/lib/libstdc++.so.6
#10 0x008b2167 in std::basic_string<char, std::char_traits, std::allocator >::basic_string(std::basic_string<char, std::char_traits, std::allocator > const&) () from /usr/lib/libstdc++.so.6
#11 0x005545e7 in hazelcast::client::connection::ClientConnectionManagerImpl::ShutdownTask::getName() const () from /opt/engine/lib/libHazelcastClient3.10-BETA-1_32.so
#12 0x08183995 in hazelcast::util::Thread::runnableThread (args=0x9ef1830) at ../target/deps/hazelcast-cpp-client-3.10-BETA-1/include/hazelcast/util/PosixThread.inl:81
#13 0x00224bc9 in start_thread () from /lib/libpthread.so.0
#14 0x0266f04e in clone () from /lib/libc.so.6

Following trace info seen:

Jun 18, 2018 04:32:36 PM INFO: [4120734576] hz.client_2[eiconfig] [3.10-BETA-1] Setting ClientConnection{alive=1, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:32:36.916000, closedTime=never, lastHeartbeatRequested=never, lastHeartbeatReceived=never, isHeartbeating=1, connected server version=3.8.2} as owner with principal uuid: f9260e2c-f446-4205-8e2f-af5fc7ce445d ownerUuid: c730f8da-916d-44e9-9407-2bc3f45c23a5
Jun 18, 2018 04:32:36 PM INFO: [4120734576] hz.client_2[eiconfig] [3.10-BETA-1] Authenticated with server Address[10.7.5.228:5701], server version:3.8.2 Local address: Address[10.7.5.151:56432]
Jun 18, 2018 04:32:37 PM INFO: [78891888] hz.client_2[eiconfig] [3.10-BETA-1]

Members [1] {
Member[10.7.5.228]:5701 - c730f8da-916d-44e9-9407-2bc3f45c23a5
}

Jun 18, 2018 04:32:37 PM INFO: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent CLIENT_CONNECTED

Jun 18, 2018 04:34:06 PM WARNING: [4053789552] hz.client_2[eiconfig] [3.10-BETA-1] Heartbeat failed over the connection: ClientConnection{alive=1, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:33:05.289000, closedTime=never, lastHeartbeatRequested=2018-06-18 15:33:56.895000, lastHeartbeatReceived=never, isHeartbeating=1, connected server version=3.8.2}
Jun 18, 2018 04:34:06 PM WARNING: [4053789552] hz.client_2[eiconfig] [3.10-BETA-1] ClientConnection{alive=0, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:33:05.289000, closedTime=2018-06-18 15:34:06.896000, lastHeartbeatRequested=2018-06-18 15:33:56.895000, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=3.8.2} closed. Reason: DefaultClientConnectionStrategy::onHeartbeatStopped[Heartbeat timed out to owner connection ClientConnection{alive=1, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:33:05.289000, closedTime=never, lastHeartbeatRequested=2018-06-18 15:33:56.895000, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=3.8.2}]TargetDisconnectedException {Heartbeat timed out to owner connection ClientConnection{alive=1, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:33:05.289000, closedTime=never, lastHeartbeatRequested=2018-06-18 15:33:56.895000, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=3.8.2} Error code:55} at DefaultClientConnectionStrategy::onHeartbeatStopped
Jun 18, 2018 04:34:06 PM INFO: [4053789552] hz.client_2[eiconfig] [3.10-BETA-1] Removed connection to endpoint: Address[10.7.5.228:5701], connection: ClientConnection{alive=0, connectionId=1, remoteEndpoint=Address[10.7.5.228:5701], lastReadTime=2018-06-18 15:33:05.289000, closedTime=2018-06-18 15:34:06.896000, lastHeartbeatRequested=2018-06-18 15:33:56.895000, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=3.8.2}
Jun 18, 2018 04:34:06 PM INFO: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent CLIENT_DISCONNECTED
Jun 18, 2018 04:34:06 PM INFO: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Trying to connect to Address[10.7.5.228:5701] as owner member
Jun 18, 2018 04:34:06 PM WARNING: [134110064] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0xeb6e8690
Jun 18, 2018 04:34:06 PM WARNING: [134110064] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0xeb6e8690
Jun 18, 2018 04:34:06 PM WARNING: [134110064] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0xeb6e8690
Jun 18, 2018 04:34:06 PM WARNING: [134110064] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0xf2602100
Jun 18, 2018 04:34:06 PM WARNING: [4120734576] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0x9c79fd0
Jun 18, 2018 04:34:06 PM WARNING: [111631216] hz.client_2[eiconfig] [3.10-BETA-1] Error while fetching cluster partition table! Cause:0x9cdf070
Jun 18, 2018 04:34:11 PM WARNING: [4120734576] hz.client_2[eiconfig] [3.10-BETA-1] ClientConnection{alive=0, connectionId=2, remoteEndpoint=null, lastReadTime=2018-06-18 15:34:06.896000, closedTime=2018-06-18 15:34:11.897000, lastHeartbeatRequested=never, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=} closed. Reason: TimeoutAuthenticationTask::TimeoutAuthenticationTask[Authentication response did not come back in 5000 millis]TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask
Jun 18, 2018 04:34:11 PM WARNING: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Exception during initial connection to Address[10.7.5.228:5701], exception ExecutionException {Could not be authenticated. Error code:19, Caused by:TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask} at AuthenticationFuture::get
Jun 18, 2018 04:34:11 PM WARNING: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Unable to get alive cluster connection, try in 0 ms later, attempt 1 of 2.
Jun 18, 2018 04:34:11 PM INFO: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Trying to connect to Address[10.7.5.228:5701] as owner member
Jun 18, 2018 04:34:11 PM WARNING: [4120734576] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details IOException {Packet not sent to null Error code:24} at AbstractClientInvocationService::send
Jun 18, 2018 04:34:16 PM WARNING: [134110064] hz.client_2[eiconfig] [3.10-BETA-1] ClientConnection{alive=0, connectionId=3, remoteEndpoint=null, lastReadTime=2018-06-18 15:34:11.901000, closedTime=2018-06-18 15:34:16.901000, lastHeartbeatRequested=never, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=} closed. Reason: TimeoutAuthenticationTask::TimeoutAuthenticationTask[Authentication response did not come back in 5000 millis]TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask
Jun 18, 2018 04:34:16 PM WARNING: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Exception during initial connection to Address[10.7.5.228:5701], exception ExecutionException {Could not be authenticated. Error code:19, Caused by:TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask} at AuthenticationFuture::get
Jun 18, 2018 04:34:16 PM WARNING: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Unable to get alive cluster connection, attempt 2 of 2.
Jun 18, 2018 04:34:16 PM WARNING: [57912176] hz.client_2[eiconfig] [3.10-BETA-1] Could not connect to cluster, shutting down the client. Unable to connect to any address! The following addresses were tried: { Address[10.7.5.228:5701] , }
Jun 18, 2018 04:34:16 PM INFO: [2519169904] hz.client_2[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent SHUTTING_DOWN
Jun 18, 2018 04:34:16 PM WARNING: [2519169904] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details HazelcastClientNotActiveException {Client is shutting down Error code:21, Caused by:HazelcastClientNotActiveException {Client is shutting down Error code:21} at AbstractClientInvocationService::shutdown} at AbstractClientInvocationService::shutdown
Jun 18, 2018 04:34:16 PM WARNING: [2582109040] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM WARNING: [2571619184] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM WARNING: [2561129328] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM WARNING: [2550639472] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM WARNING: [2540149616] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM WARNING: [2529659760] hz.client_2[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details RejectedExecutionException {Executor is terminated! Error code:46} at SimpleExecutor::execute
Jun 18, 2018 04:34:16 PM INFO: [2519169904] hz.client_2[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent SHUTDOWN
Jun 18, 2018 04:34:16 PM INFO: [4099754864] hz.client_3[eiconfig] [3.10-BETA-1] (NOT_FOUND:NOT_FOUND) LifecycleService::LifecycleEvent STARTING
Jun 18, 2018 04:34:16 PM INFO: [4099754864] hz.client_3[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent STARTED
Jun 18, 2018 04:34:16 PM INFO: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Trying to connect to Address[10.7.5.228:5701] as owner member
Jun 18, 2018 04:34:21 PM WARNING: [4078775152] hz.client_3[eiconfig] [3.10-BETA-1] ClientConnection{alive=0, connectionId=1, remoteEndpoint=null, lastReadTime=2018-06-18 15:34:16.935000, closedTime=2018-06-18 15:34:21.937000, lastHeartbeatRequested=never, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=} closed. Reason: TimeoutAuthenticationTask::TimeoutAuthenticationTask[Authentication response did not come back in 5000 millis]TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask
Jun 18, 2018 04:34:21 PM WARNING: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Exception during initial connection to Address[10.7.5.228:5701], exception ExecutionException {Could not be authenticated. Error code:19, Caused by:TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask} at AuthenticationFuture::get
Jun 18, 2018 04:34:21 PM WARNING: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Unable to get alive cluster connection, try in 0 ms later, attempt 1 of 2.
Jun 18, 2018 04:34:21 PM INFO: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Trying to connect to Address[10.7.5.228:5701] as owner member
Jun 18, 2018 04:34:22 PM WARNING: [2519169904] hz.client_3[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details IOException {Packet not sent to null Error code:24} at AbstractClientInvocationService::send
Jun 18, 2018 04:34:26 PM WARNING: [4064279408] hz.client_3[eiconfig] [3.10-BETA-1] ClientConnection{alive=0, connectionId=2, remoteEndpoint=null, lastReadTime=2018-06-18 15:34:21.940000, closedTime=2018-06-18 15:34:26.941000, lastHeartbeatRequested=never, lastHeartbeatReceived=never, isHeartbeating=0, connected server version=} closed. Reason: TimeoutAuthenticationTask::TimeoutAuthenticationTask[Authentication response did not come back in 5000 millis]TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask
Jun 18, 2018 04:34:26 PM WARNING: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Exception during initial connection to Address[10.7.5.228:5701], exception ExecutionException {Could not be authenticated. Error code:19, Caused by:TimeoutException {Authentication response did not come back in 5000 millis Error code:57} at TimeoutAuthenticationTask::TimeoutAuthenticationTask} at AuthenticationFuture::get
Jun 18, 2018 04:34:26 PM WARNING: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Unable to get alive cluster connection, attempt 2 of 2.
Jun 18, 2018 04:34:26 PM WARNING: [51526512] hz.client_3[eiconfig] [3.10-BETA-1] Could not connect to cluster, shutting down the client. Unable to connect to any address! The following addresses were tried: { Address[10.7.5.228:5701] , }
Jun 18, 2018 04:34:26 PM INFO: [4099754864] hz.client_3[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent SHUTTING_DOWN
Jun 18, 2018 04:34:26 PM WARNING: [4099754864] hz.client_3[eiconfig] [3.10-BETA-1] Future.set_exception should not be called twice : details HazelcastClientNotActiveException {Client is shutting down Error code:21, Caused by:HazelcastClientNotActiveException {Client is shutting down Error code:21} at AbstractClientInvocationService::shutdown} at AbstractClientInvocationService::shutdown
Jun 18, 2018 04:34:26 PM INFO: [4099754864] hz.client_3[eiconfig] [3.10-BETA-1] LifecycleService::LifecycleEvent SHUTDOWN

[siwhiting]

issue_429_info_threads.txt

[ihsandemir]

I just submitted a fix for the problem: #430 Is it possible that you can try this fix? I can provide you the library binary for your trial if you tell me which binary lib you are using?

[ihsandemir]

This is the same issue as #428

[ihsandemir]

Hello @siwhiting , did you get a chance to try my fix PR branch? I would like to confirm that the PR solves the problem before merging it.

[siwhiting]

I've added fix to code and it's now crashing due to an invalid mutex (see bt below)

#0 0x0018544d in pthread_mutex_lock () from /lib/libpthread.so.0
#1 0x010a4b05 in hazelcast::util::Mutex::lock (this=0x47c) at /home/swhiting/dev/third-party/hazelcast-3.10-BETA-1-ei/hazelcast/src/hazelcast/util/Mutex.cpp:73
#2 0x010a4569 in hazelcast::util::LockGuard::LockGuard (this=0xe61f6e70, mutex=...)
at /home/swhiting/dev/third-party/hazelcast-3.10-BETA-1-ei/hazelcast/src/hazelcast/util/LockGuard.cpp:26
#3 0x010a4894 in hazelcast::util::AtomicBoolean::compareAndSet (this=0x47c, compareValue=true, setValue=false)
at /home/swhiting/dev/third-party/hazelcast-3.10-BETA-1-ei/hazelcast/src/hazelcast/util/AtomicBoolean.cpp:44
#4 0x00fa301e in hazelcast::client::spi::LifecycleService::shutdown (this=0x444)
at /home/swhiting/dev/third-party/hazelcast-3.10-BETA-1-ei/hazelcast/src/hazelcast/client/spi/LifecycleService.cpp:73
#5 0x0102ea54 in hazelcast::client::connection::ClientConnectionManagerImpl::ShutdownTask::run (this=0xf2479b30)
at /home/swhiting/dev/third-party/hazelcast-3.10-BETA-1-ei/hazelcast/src/hazelcast/client/connection/ClientConnectionManagerImpl.cpp:825
#6 0x081835f4 in hazelcast::util::Thread::runnableThread (args=0xf2479b30) at ../target/deps/hazelcast-cpp-client-3.10-BETA-1/include/hazelcast/util/PosixThread.inl:70
#7 0x00183bc9 in start_thread () from /lib/libpthread.so.0
#8 0x0062c04e in clone () from /lib/libc.so.6

Note issue 429 is very easy to reproduce if you've a cpp client and server program.

[siwhiting]

To use 'tcpkill', dsniff package needs to be installed on Hazelcast server node.
Can then ps to find out port of the client connected to Hazelcast server.

tcpkill -9 port

Alternatively, just attach to the Hazelcast server pid using gbd, and wait 2 mins

[ihsandemir]

@siwhiting Thanks for the info. I am trying this scenario but it does not match yours since the client does not go out of scope and hence is not destructed, can you tell me from the below code, what is different from yours?:

            TEST_F(ClientConnectionTest, testCrash) {
                // starts a server
                HazelcastServer instance(*g_srvFactory);
                ClientConfig config;
                config.setProperty(ClientProperties::PROP_HEARTBEAT_TIMEOUT, "5");
                config.setProperty(ClientProperties::PROP_HEARTBEAT_INTERVAL, "1");
                HazelcastClient client(config);
                sleep(INT32_MAX);
            }

Under which condition does your client go out of scope?

(I used debugger to stop the server process)

I just realized that I was trying the master branch which may be a little different from the 3.10-BETA-1 release since we had this PR at the master: #423

I will now try with the v3.10-BETA-1 tag.

[ihsandemir]

Hello @siwhiting I tried the code with the v3.10-BETA-1 tag but I could not reproduce the problem. I need some clues on how you destruct the client on your example. Any help for the reproducer test is appreciated.

[ihsandemir]

This is the same issue as #428 hence closing this issue and will continue with issue #428.