fix(tests): making test_read_only test less flaky

Author: StephenSorriaux

kazoo/protocol/connection.py

@@ -544,9 +544,9 @@ def zk_loop(self):
                 if retry(self._connect_loop, retry) is STOP_CONNECTING:
                     break
         except RetryFailedError:
-            self.logger.warning(
+            self.logger.exception(
                 "Failed connecting to Zookeeper "
-                "within the connection retry policy."
+                "within the connection retry policy:"
             )
         finally:
             self.connection_stopped.set()

kazoo/testing/common.py

@@ -221,8 +221,9 @@ def run(self):
         )
         self.process = subprocess.Popen(args=args)
         log.info(
-            "Started zookeeper process %s using args %s",
+            "Started zookeeper process %s on port %s using args %s",
             self.process.pid,
+            self.server_info.client_port,
             args,
         )
         self._running = True
@@ -304,12 +305,12 @@ def destroy(self):
 
         shutil.rmtree(self.working_path, True)
 
-    def get_logs(self):
+    def get_logs(self, num_lines=100):
         log_path = pathlib.Path(self.working_path, "zookeeper.log")
         if log_path.exists():
             log_file = log_path.open("r")
             lines = log_file.readlines()
-            return lines[-100:]
+            return lines[-num_lines:]
         return []
 
 

kazoo/tests/conftest.py

@@ -4,8 +4,10 @@
 
 
 def pytest_exception_interact(node, call, report):
-    if hasattr(node._testcase, "cluster"):
+    try:
         cluster = node._testcase.cluster
         log.error("Zookeeper cluster logs:")
         for logs in cluster.get_logs():
             log.error(logs)
+    except Exception:
+        log.exception("Cant get ZK logs:")

kazoo/tests/test__connection.py renamed to kazoo/tests/test_connection.py

@@ -1,4 +1,6 @@
 from collections import namedtuple, deque
+import logging
+
 import os
 import threading
 import time
@@ -18,8 +20,10 @@
 from kazoo.protocol.states import KazooState
 from kazoo.protocol.connection import _CONNECTION_DROP
 from kazoo.testing import KazooTestCase
-from kazoo.tests.util import wait
-from kazoo.tests.util import CI_ZK_VERSION
+from kazoo.tests.util import wait, CI_ZK_VERSION, CI
+
+
+log = logging.getLogger(__name__)
 
 
 class Delete(namedtuple("Delete", "path version")):
@@ -258,7 +262,7 @@ def back(state):
 class TestReadOnlyMode(KazooTestCase):
     def setUp(self):
         os.environ["ZOOKEEPER_LOCAL_SESSION_RO"] = "true"
-        self.setup_zookeeper(read_only=True)
+        self.setup_zookeeper()
         skip = False
         if CI_ZK_VERSION and CI_ZK_VERSION < (3, 4):
             skip = True
@@ -279,7 +283,15 @@ def test_read_only(self):
         from kazoo.exceptions import NotReadOnlyCallError
         from kazoo.protocol.states import KeeperState
 
-        client = self.client
+        if CI:
+            # force some wait to make sure the data produced during the
+            # `setUp()` step are replicaed to all zk members
+            # if not done the `get_children()` test may fail because the
+            # node does not exist on the node that we will keep alive
+            time.sleep(15)
+        # do not keep the client started in the `setUp` step alive
+        self.client.stop()
+        client = self._get_client(read_only=True)
         states = []
         ev = threading.Event()
 
@@ -289,6 +301,7 @@ def listen(state):
             if client.client_state == KeeperState.CONNECTED_RO:
                 ev.set()
 
+        client.start()
         try:
             # stopping both nodes at the same time
             # else the test seems flaky when on CI hosts
@@ -303,6 +316,11 @@ def listen(state):
                 thread.start()
             for thread in zk_stop_threads:
                 thread.join()
+            # stopping the client is *mandatory*, else the client might try to
+            # reconnect using a xid that the server may endlessly refuse
+            # stopping the client makes sure the xid is resetted
+            client.stop()
+            client.start()
             ev.wait(15)
             assert ev.is_set()
             assert client.client_state == KeeperState.CONNECTED_RO

kazoo/tests/test_lock.py

@@ -511,7 +511,8 @@ def test_rw_lock(self):
 
             with self.condition:
                 while not self.active_thread:
-                    self.condition.wait()
+                    success = self.condition.wait(timeout=10)
+                    assert success
                 assert self.active_thread == contender
 
             assert lock.contenders() == remaining
@@ -521,7 +522,8 @@ def test_rw_lock(self):
 
             with self.condition:
                 while self.active_thread:
-                    self.condition.wait()
+                    success = self.condition.wait(timeout=10)
+                    assert success
 
         reader_thread.join()
         writer_thread.join()

pyproject.toml

@@ -21,6 +21,11 @@ extend-exclude = '''
 
 [tool.pytest.ini_options]
 addopts = "-ra -v"
+# XXX: uncomment if in need off all the captured logs with timing and stuff
+# log_cli = true
+# log_cli_date_format = "%Y-%m-%d %H:%M:%S"
+# log_cli_format = "%(asctime)s %(levelname)s %(message)s"
+# log_cli_level = "INFO"
 
 [tool.mypy]
 
@@ -114,11 +119,11 @@ module = [
     'kazoo.testing.common',
     'kazoo.testing.harness',
     'kazoo.tests.conftest',
-    'kazoo.tests.test__connection',
     'kazoo.tests.test_barrier',
     'kazoo.tests.test_build',
     'kazoo.tests.test_cache',
     'kazoo.tests.test_client',
+    'kazoo.tests.test_connection',
     'kazoo.tests.test_counter',
     'kazoo.tests.test_election',
     'kazoo.tests.test_eventlet_handler',

tox.ini

@@ -36,7 +36,7 @@ allowlist_externals =
 commands =
     sasl: {toxinidir}/init_krb5.sh {envtmpdir}/kerberos \
         {toxinidir}/ensure-zookeeper-env.sh \
-        pytest {posargs: -ra -v --cov-report=xml --cov=kazoo kazoo/tests}
+        pytest {posargs: -ra -v --cov-report=xml --cov=kazoo kazoo/tests/test_connection.py}
 
 [testenv:build]