CountdownLatchTest failure (https://hazelcast-l337.ci.cloudbees.com/view/Clients/job/cpp-linux-nightly/39)

[ihsandemir]

Fix for CountdownLatchTest failure in some runs (e.g.: https://hazelcast-l337.ci.cloudbees.com/view/Clients/job/cpp-linux-nightly/39/ ). This comes out to be a missing thread wait in the test itself.

Related to #76

The problem is generated under these conditions:

1. OS is centos.
2. Build 64 bit static Release. Debug build can not produce the case.
3. No log before Future.get: conditionVariable.waitFor(mutex, endTime - time(NULL));

[sancar]

But there is already thread.join in destructor of thread. This change does not affect the test. If problem is really timing, we can increase the timeout to 2 minutes(default of timeouts in java tests). If latch takes 2 minutes to finish, we can easily conclude that implementation is wrong.

[ihsandemir]

Sancar,

The thread destructor also has the pthread_cancel just before pthread_join, i don't know if that causes the problem. I don't think it is a timing problem of 2 minutes, the test really passes most of the time. (I separately checked the timing for await, it is doing the wait as requested, hence we can assume it is working)

Still need to understand why LockGuard destructor is getting the Segmentation fault. It only does mutex.unlock(), may be the mutex becoming invalid by then, i could not understand this yet.

From the stack trace we see that it is possible to get to thread destructor before testLatchThread function completes. This shows that the main thread assertTrue(l->await(10 * 1000)); lines passed before the testLatchThread function finishes. Hence, this suggested to me that the response to await call may arrive earlier than the response to the last countDown call (may be due to the times the server delivers these responses may be different). But we really want the testLatchThread to exit before the l.await passes and the test scope ends, don't we?

Stack trace:

Core was generated by `buildSHARED64Release/hazelcast/test/clientTest_SHARED_64'.
Program terminated with signal 11, Segmentation fault.

[Switching to thread 1 (Thread 28818)]#0 0x00002b2706df8bf0 in hazelcast::util::LockGuard::~LockGuard() ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
(gdb) bt
#0 0x00002b2706df8bf0 in hazelcast::util::LockGuard::~LockGuard() ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#1 0x00002b2706dac47f in hazelcast::client::connection::CallFuture::get(long) ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#2 0x00002b2706daca65 in hazelcast::client::connection::CallFuture::get() ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#3 0x00002b2706dbdefe in hazelcast::client::proxy::ProxyImpl::invoke(std::auto_ptrhazelcast::client::protocol::ClientMessage, int) ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#4 0x00002b2706db381b in hazelcast::client::ICountDownLatch::countDown() ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#5 0x0000000000474078 in hazelcast::client::test::testLatchThread(hazelcast::util::ThreadArgs&) ()
#6 0x00002b2706df8703 in hazelcast::util::Thread::controlledThread(void*) ()
from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#7 0x000000338880683d in start_thread () from /lib64/libpthread.so.0
#8 0x0000003387cd4fdd in clone () from /lib64/libc.so.6

(gdb) thread 7
[Switching to thread 7 (Thread 0x2b27070d5980 (LWP 27708))]#0 0x0000003388807c65 in pthread_join () from /lib64/libpthread.so.0
(gdb) bt
#0 0x0000003388807c65 in pthread_join () from /lib64/libpthread.so.0
#1 0x00002b2706df812c in hazelcast::util::Thread::join() () from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#2 0x00002b2706df8243 in hazelcast::util::Thread::~Thread() () from /root/jenkins/workspace/cpp-linux-nightly/buildSHARED64Release/libHazelcastClient3.7-SNAPSHOT_64.so
#3 0x0000000000478914 in hazelcast::client::test::ICountDownLatchTest::testLatch() ()
#4 0x0000000000480fd5 in iTest::iTestFixturehazelcast::client::test::ICountDownLatchTest::executeTests() ()
#5 0x000000000047aca8 in unitTests(char const*) ()
#6 0x0000003387c1d9f4 in __libc_start_main () from /lib64/libc.so.6
#7 0x00000000004423b9 in _start ()

[sancar]

From the stack trace we see that it is possible to get to thread destructor before testLatchThread function completes.

Is not this because timeout is something that can be reachable when there is load on the system? If we make it a bigger value, test will be more healthy.

This shows that the main thread assertTrue(l->await(10 * 1000)); lines passed before the testLatchThread function finishes. Hence, this suggested to me that the response to await call may arrive earlier than the response to the last countDown call .

This is again 10 seconds is too short for this case.

But we really want the testLatchThread to exit before the l.await passes and the test scope ends, don't we?
It should not matter which one happens first. Threads finished or await passes. Either way test will pass.

By the way, do we know which LockGuard/mutex causes the problem ?

[ihsandemir]

@sancar there is a check for await return assertTrue(l->await(10 * 1000)); This checks passed, meaning that it was not a timeout, does it make sense? We don't have any load on the server.

The guard/mutex here: https://github.com/hazelcast/hazelcast-cpp-client/blob/master/hazelcast/src/hazelcast/client/connection/CallFuture.cpp line 73, and then https://github.com/hazelcast/hazelcast-cpp-client/blob/master/hazelcast/include/hazelcast/util/Future.h#L88

[sancar]

What if it failed when there is a timeout
Test throws an exception
Causes hazelcast to be closed which makes mutex invalid(this should not be possible because of reference counting via shared_ptr)
And this causes core dump because other thread waiting on mutex.
Because of core dump we don't see the test exception properly.

Do we know how much time test takes when it failed ?

[ihsandemir]

Test log: https://hazelcast-l337.ci.cloudbees.com/view/Clients/job/cpp-linux-nightly/39/console

According to time stamp in the test: started and ended at 19:56:37. It really lasted short.

Which timeout? Timeout in await call? Because, there is no timeout for C++ test run, it can only be either boolean false from the server or some other exception message. I tested both cases:

// throw IException in await call, the test result:
<<<<<<< ICountDownLatchTest >>>>>>
======= 0. ICountDownLatchTest =======
ExceptionMessage {ihsan} at Server:
============FAILED==============

// Put sleep(25) in testLatchThread, result:
<<<<<<< ICountDownLatchTest >>>>>>
======= 0. ICountDownLatchTest =======
Assert[ 3 ] is failed.
============FAILED==============

[devOpsHazelcast]

Test PASSed.

[devOpsHazelcast]

Test PASSed.