Add more logging for flaky add_distributed_object_listener_object_des… (#283)

* Add more logging for flaky add_distributed_object_listener_object_destroyed test

The test failed again recently on the nightly test runner. I could not
reproduce the problem locally, or see a problem in the implementation or test.

To understand the situation better, improved the `assertTrueEventually` utility
method to raise the last error occured and added a context manager
to change the log level for the duration of the test.

Also, improved some parts of the `add_distributed_object_listener` by removing
some unncessary closure definitions.

* display assertion errors better in Python2

Author: mdumandag

hazelcast/client.py

@@ -530,23 +530,19 @@ def add_distributed_object_listener(self, listener_func):
             hazelcast.future.Future[str]: A registration id which is used as a key to remove the listener.
         """
         is_smart = self.config.smart_routing
-        request = client_add_distributed_object_listener_codec.encode_request(is_smart)
+        codec = client_add_distributed_object_listener_codec
+        request = codec.encode_request(is_smart)
 
         def handle_distributed_object_event(name, service_name, event_type, source):
             event = DistributedObjectEvent(name, service_name, event_type, source)
             listener_func(event)
 
         def event_handler(client_message):
-            return client_add_distributed_object_listener_codec.handle(client_message, handle_distributed_object_event)
+            return codec.handle(client_message, handle_distributed_object_event)
 
-        def decode_add_listener(response):
-            return client_add_distributed_object_listener_codec.decode_response(response)
-
-        def encode_remove_listener(registration_id):
-            return client_remove_distributed_object_listener_codec.encode_request(registration_id)
-
-        return self._listener_service.register_listener(request, decode_add_listener,
-                                                        encode_remove_listener, event_handler)
+        return self._listener_service.register_listener(request, codec.decode_response,
+                                                        client_remove_distributed_object_listener_codec.encode_request,
+                                                        event_handler)
 
     def remove_distributed_object_listener(self, registration_id):
         """Removes the specified distributed object listener.

tests/base.py

@@ -1,7 +1,10 @@
 import logging
+import sys
 import time
 import unittest
 from threading import Thread
+
+from hazelcast import six
 from tests.hzrc.client import HzRemoteController
 import hazelcast
 from hazelcast.core import Address
@@ -58,13 +61,19 @@ def shutdown_all_clients(self):
 
     def assertTrueEventually(self, assertion, timeout=30):
         timeout_time = time.time() + timeout
+        exc_info = None
         while time.time() < timeout_time:
             try:
                 assertion()
                 return
             except AssertionError:
+                exc_info = sys.exc_info()
                 time.sleep(0.1)
-        raise
+
+        if exc_info is None:
+            raise Exception("Could not enter the assertion loop!")
+
+        six.reraise(*exc_info)
 
     def assertSetEventually(self, event, timeout=5):
         is_set = event.wait(timeout)

tests/proxy/distributed_objects_test.py

@@ -1,11 +1,12 @@
+import logging
 import time
 
 import hazelcast
 from hazelcast.core import DistributedObjectEventType
 
 from hazelcast.proxy import MAP_SERVICE
 from tests.base import SingleMemberTestCase
-from tests.util import event_collector
+from tests.util import event_collector, LoggingContext
 from hazelcast import six
 
 
@@ -65,18 +66,19 @@ def assert_event():
         self.assertTrueEventually(assert_event)
 
     def test_add_distributed_object_listener_object_destroyed(self):
-        collector = event_collector()
-        m = self.client.get_map("test-map")
-        self.client.add_distributed_object_listener(listener_func=collector).result()
+        with LoggingContext(logging.getLogger(), logging.DEBUG):
+            collector = event_collector()
+            m = self.client.get_map("test-map")
+            self.client.add_distributed_object_listener(listener_func=collector).result()
 
-        m.destroy()
+            m.destroy()
 
-        def assert_event():
-            self.assertEqual(1, len(collector.events))
-            event = collector.events[0]
-            self.assertDistributedObjectEvent(event, "test-map", MAP_SERVICE, DistributedObjectEventType.DESTROYED)
+            def assert_event():
+                self.assertEqual(1, len(collector.events))
+                event = collector.events[0]
+                self.assertDistributedObjectEvent(event, "test-map", MAP_SERVICE, DistributedObjectEventType.DESTROYED)
 
-        self.assertTrueEventually(assert_event)
+            self.assertTrueEventually(assert_event)
 
     def test_add_distributed_object_listener_object_created_and_destroyed(self):
         collector = event_collector()

tests/util.py

@@ -86,3 +86,15 @@ def open_connection_to_address(client, uuid):
     m.put(key, 0)
     m.destroy()
 
+
+class LoggingContext(object):
+    def __init__(self, logger, level):
+        self.logger = logger
+        self.level = level
+        self.old_level = logger.level
+
+    def __enter__(self):
+        self.logger.setLevel(self.level)
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        self.logger.setLevel(self.old_level)