Flaky test_rolling_upgrade
[cassandra-dtest.git] / cql_test.py
index f49e6270d2388a2dfbaf32c9c9b8bd15b5883168..99d3088cede903d7955695d89d8f6be7762920c2 100644 (file)
@@ -1,4 +1,5 @@
 import itertools
+import re
 import struct
 import time
 import pytest
@@ -11,7 +12,7 @@ from cassandra.metadata import NetworkTopologyStrategy, SimpleStrategy
 from cassandra.policies import FallthroughRetryPolicy
 from cassandra.query import SimpleStatement
 
-from dtest import Tester, create_ks
+from dtest import Tester, create_ks, mk_bman_path
 from distutils.version import LooseVersion
 from thrift_bindings.thrift010.ttypes import \
     ConsistencyLevel as ThriftConsistencyLevel
@@ -53,7 +54,7 @@ class CQLTester(Tester):
             cluster.set_configuration_options(values=config)
 
         if not cluster.nodelist():
-            cluster.populate(nodes).start(wait_for_binary_proto=True)
+            cluster.populate(nodes).start()
         node1 = cluster.nodelist()[0]
 
         session = self.patient_cql_connection(node1, protocol_version=protocol_version, user=user, password=password)
@@ -731,7 +732,7 @@ class TestMiscellaneousCQL(CQLTester):
         """
 
         cluster = self.cluster
-
+        cluster.set_configuration_options({'enable_drop_compact_storage': 'true'})
         cluster.populate(3).start()
         node1, node2, node3 = cluster.nodelist()
 
@@ -764,6 +765,38 @@ class TestMiscellaneousCQL(CQLTester):
                         [2, None, 2, None],
                         [3, None, 3, None]])
 
+    @since("4.0")
+    def test_truncate_failure(self):
+        """
+        @jira_ticket CASSANDRA-16208
+        Tests that if a TRUNCATE query fails on some replica, the coordinator will immediately return an error to the
+        client instead of waiting to time out because it couldn't get the necessary number of success acks.
+        """
+        cluster = self.cluster
+        cluster.populate(3, install_byteman=True).start()
+        node1, _, node3 = cluster.nodelist()
+        node3.byteman_submit([mk_bman_path('truncate_fail.btm')])
+
+        session = self.patient_exclusive_cql_connection(node1)
+        create_ks(session, 'ks', 3)
+
+        logger.debug("Creating data table")
+        session.execute("CREATE TABLE data (id int PRIMARY KEY, data text)")
+        session.execute("UPDATE data SET data = 'Awesome' WHERE id = 1")
+
+        self.fixture_dtest_setup.ignore_log_patterns = ['Dummy failure']
+        logger.debug("Truncating data table (error expected)")
+
+        thrown = False
+        exception = None
+        try:
+            session.execute("TRUNCATE data")
+        except Exception as e:
+            exception = e
+            thrown = True
+
+        assert thrown, "No exception has been thrown"
+        assert re.search("Truncate failed on replica /127.0.0.3", str(exception)) is not None
 
 @since('3.2')
 class AbortedQueryTester(CQLTester):
@@ -803,8 +836,7 @@ class AbortedQueryTester(CQLTester):
         # introduced by CASSANDRA-7392 to pause by the specified amount of milliseconds every
         # CQL row iterated for non system queries, so that these queries take much longer to complete,
         # see ReadCommand.withStateTracking()
-        cluster.populate(1).start(wait_for_binary_proto=True,
-                                  jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
+        cluster.populate(1).start(jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
                                             "-Dcassandra.test.read_iteration_delay_ms=5"])
         node = cluster.nodelist()[0]
         session = self.patient_cql_connection(node)
@@ -919,8 +951,7 @@ class AbortedQueryTester(CQLTester):
                                                   'read_request_timeout_in_ms': 1000,
                                                   'range_request_timeout_in_ms': 1000})
 
-        cluster.populate(1).start(wait_for_binary_proto=True,
-                                  jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
+        cluster.populate(1).start(jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
                                             "-Dcassandra.test.read_iteration_delay_ms=5"])  # see above for explanation
         node = cluster.nodelist()[0]
         session = self.patient_cql_connection(node)
@@ -1034,58 +1065,12 @@ class TestCQLSlowQuery(CQLTester):
         # introduced by CASSANDRA-7392 to pause by the specified amount of milliseconds during each
         # iteration of non system queries, so that these queries take much longer to complete,
         # see ReadCommand.withStateTracking()
-        cluster.populate(1).start(wait_for_binary_proto=True,
-                                  jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
+        cluster.populate(1).start(jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
                                             "-Dcassandra.test.read_iteration_delay_ms=1"])
         node = cluster.nodelist()[0]
         session = self.patient_cql_connection(node)
 
-        create_ks(session, 'ks', 1)
-        session.execute("""
-            CREATE TABLE test1 (
-                id int,
-                col int,
-                val text,
-                PRIMARY KEY(id, col)
-            );
-        """)
-
-        for i in range(100):
-            session.execute("INSERT INTO test1 (id, col, val) VALUES (1, {}, 'foo')".format(i))
-
-        # only check debug logs because at INFO level the no-spam logger has unpredictable results
-        mark = node.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test1",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node.watch_log_for(["operations were slow", "SELECT \* FROM ks.test1"],
-                           from_mark=mark, filename='debug.log', timeout=60)
-        mark = node.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test1 where id = 1",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node.watch_log_for(["operations were slow", "SELECT \* FROM ks.test1"],
-                           from_mark=mark, filename='debug.log', timeout=60)
-        mark = node.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test1 where id = 1",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node.watch_log_for(["operations were slow", "SELECT \* FROM ks.test1"],
-                           from_mark=mark, filename='debug.log', timeout=60)
-        mark = node.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test1 where token(id) < 0",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node.watch_log_for(["operations were slow", "SELECT \* FROM ks.test1"],
-                           from_mark=mark, filename='debug.log', timeout=60)
+        self._assert_logs_slow_queries(node, session)
 
     def test_remote_query(self):
         """
@@ -1105,7 +1090,7 @@ class TestCQLSlowQuery(CQLTester):
         @jira_ticket CASSANDRA-12403
         """
         cluster = self.cluster
-        cluster.set_configuration_options(values={'slow_query_log_timeout_in_ms': 10,
+        cluster.set_configuration_options(values={'slow_query_log_timeout_in_ms': 1,
                                                   'request_timeout_in_ms': 120000,
                                                   'read_request_timeout_in_ms': 120000,
                                                   'range_request_timeout_in_ms': 120000})
@@ -1116,55 +1101,11 @@ class TestCQLSlowQuery(CQLTester):
         node1.start(wait_for_binary_proto=True, join_ring=False)  # ensure other node executes queries
         node2.start(wait_for_binary_proto=True,
                     jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
-                              "-Dcassandra.test.read_iteration_delay_ms=1"])  # see above for explanation
+                              "-Dcassandra.test.read_iteration_delay_ms=2"])  # see above for explanation
 
         session = self.patient_exclusive_cql_connection(node1)
 
-        create_ks(session, 'ks', 1)
-        session.execute("""
-            CREATE TABLE test2 (
-                id int,
-                col int,
-                val text,
-                PRIMARY KEY(id, col)
-            );
-        """)
-
-        for i, j in itertools.product(list(range(100)), list(range(10))):
-            session.execute("INSERT INTO test2 (id, col, val) VALUES ({}, {}, 'foo')".format(i, j))
-
-        # only check debug logs because at INFO level the no-spam logger has unpredictable results
-        mark = node2.mark_log(filename='debug.log')
-        session.execute(SimpleStatement("SELECT * from test2",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node2.watch_log_for(["operations were slow", "SELECT \* FROM ks.test2"],
-                            from_mark=mark, filename='debug.log', timeout=60)
-        mark = node2.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test2 where id = 1",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node2.watch_log_for(["operations were slow", "SELECT \* FROM ks.test2"],
-                            from_mark=mark, filename='debug.log', timeout=60)
-        mark = node2.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test2 where id = 1",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node2.watch_log_for(["operations were slow", "SELECT \* FROM ks.test2"],
-                            from_mark=mark, filename='debug.log', timeout=60)
-        mark = node2.mark_log(filename='debug.log')
-
-        session.execute(SimpleStatement("SELECT * from test2 where token(id) < 0",
-                                        consistency_level=ConsistencyLevel.ONE,
-                                        retry_policy=FallthroughRetryPolicy()))
-
-        node2.watch_log_for(["operations were slow", "SELECT \* FROM ks.test2"],
-                            from_mark=mark, filename='debug.log', timeout=60)
+        self._assert_logs_slow_queries(node2, session)
 
     def test_disable_slow_query_log(self):
         """
@@ -1190,8 +1131,7 @@ class TestCQLSlowQuery(CQLTester):
         # introduced by CASSANDRA-7392 to pause by the specified amount of milliseconds during each
         # iteration of non system queries, so that these queries take much longer to complete,
         # see ReadCommand.withStateTracking()
-        cluster.populate(1).start(wait_for_binary_proto=True,
-                                  jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
+        cluster.populate(1).start(jvm_args=["-Dcassandra.monitoring_report_interval_ms=10",
                                             "-Dcassandra.test.read_iteration_delay_ms=1"])
         node = cluster.nodelist()[0]
         session = self.patient_cql_connection(node)
@@ -1215,7 +1155,366 @@ class TestCQLSlowQuery(CQLTester):
 
         self._check_logs(node, "SELECT \* FROM ks.test3", 'debug.log', 0)
 
-    def _check_logs(self, node, pattern, filename, num_expected):
+    @staticmethod
+    def _assert_logs_slow_queries(node, session):
+        TestCQLSlowQuery._assert_logs_slow_queries_with_skinny_table(node, session)
+        for asc in (True, False):
+            TestCQLSlowQuery._assert_logs_slow_queries_with_wide_table(node, session, asc=asc)
+
+    @staticmethod
+    def _assert_logs_slow_queries_with_skinny_table(node, session):
+        create_ks(session, 'ks', 1)
+        table = "t_skinny"
+        session.execute("""
+            CREATE TABLE {} (
+                k int,
+                v int,
+                l list<int>,
+                s set<int>,
+                m map<int, int>,
+                "Escaped_Name" int,
+                PRIMARY KEY(k)
+            );
+        """.format(table))
+
+        # insert some partitions
+        for k in range(100):
+            session.execute("INSERT INTO {} (k, v) VALUES ({}, 1)".format(table, k))
+
+        # test logging of slow queries without restricitons
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {}",
+                                      logged_query="SELECT \* FROM ks.t")
+
+        # test logging of slow queries with restriciton on token
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) < 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) < 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) > 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) <= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) <= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) >= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) >= 0")
+
+        # test logging of slow queries with restriciton on partition key
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k < 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k <= 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k <= 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k > 0 AND k <= 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k > 0 AND k <= 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k >= 0 AND k < 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k >= 0 AND k < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k <= 100 AND k > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k > 0 AND k <= 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k < 100 AND k >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k >= 0 AND k < 100")
+
+        # test logging of slow queries with restriciton on regular column
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v = 1 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v = 1")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v < 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v < 2")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v <= 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v <= 2")
+
+        # test logging of slow queries with column selections
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT v FROM {}",
+                                      logged_query="SELECT v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT l FROM {}",
+                                      logged_query="SELECT l FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT s FROM {}",
+                                      logged_query="SELECT s FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT m FROM {}",
+                                      logged_query="SELECT m FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT \"Escaped_Name\" FROM {}",
+                                      logged_query="SELECT \"Escaped_Name\" FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT v,s FROM {}",
+                                      logged_query="SELECT s, v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k,v,s FROM {}",
+                                      logged_query="SELECT s, v FROM ks.{}")
+
+        # test logging of slow queries with primary key-only column selections
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k FROM {}",
+                                      logged_query="SELECT \* FROM ks.{}")
+
+        # test logging of slow queries with sub-selections (only supported since 4.0)
+        if node.cluster.version() >= '4.0':
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT s[0] FROM {}",
+                                          logged_query="SELECT s\[0\] FROM ks.{}")
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT m[0] FROM {}",
+                                          logged_query="SELECT m\[0\] FROM ks.{}")
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT k,v,s[0],m[1] FROM {}",
+                                          logged_query="SELECT m\[1\], s\[0\], v FROM ks.{}")
+
+    @staticmethod
+    def _assert_logs_slow_queries_with_wide_table(node, session, asc=True):
+        create_ks(session, 'ks', 1)
+        table = "t_wide_asc" if asc else "t_wide_desc"
+        session.execute("""
+            CREATE TABLE {} (
+                k int,
+                c1 int,
+                c2 int,
+                v int,
+                s int STATIC,
+                lt list<int>,
+                st set<int>,
+                mp map<int, int>,
+                "Escaped_Name" int,
+                PRIMARY KEY(k, c1, c2)
+            ) WITH CLUSTERING ORDER BY (c1 {}, c2 {});
+        """.format(table, "ASC" if asc else "DESC", "ASC" if asc else "DESC"))
+
+        # insert some partitions
+        for k in range(100):
+            session.execute("INSERT INTO {} (k, c1, c2, s, v) VALUES ({}, 1, 1, 1, 1)".format(table, k))
+
+        # add some rows to one of the partitions
+        for c1 in range(100):
+            session.execute("INSERT INTO {} (k, c1, c2, s, v) VALUES (0, {}, 1, 1, 1)".format(table, c1))
+
+        # add some rows to one of the pairs partition-first clustering
+        for c2 in range(100):
+            session.execute("INSERT INTO {} (k, c1, c2, s, v) VALUES (0, 0, {}, 1, 1)".format(table, c2))
+
+        # test logging of slow queries without restricitons
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {}",
+                                      logged_query="SELECT \* FROM ks.t")
+
+        # test logging of slow queries with restriciton on token
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) < 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) < 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) > 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) <= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) <= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE token(k) >= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE token\(k\) >= 0")
+
+        # test logging of slow queries with restriciton on partition key
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k IN (0) ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k IN (0, 1) ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k < 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k <= 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k <= 100")
+
+        # test logging of slow queries with restriciton on first clustering key
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 = 1 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 = 1")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 IN (1) ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 = 1")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT v FROM {} WHERE c1 IN (1, 2) ALLOW FILTERING",
+                                      logged_query="SELECT v FROM ks.{} WHERE c1 IN \({}, {}\)"
+                                      .format(table, 1 if asc else 2, 2 if asc else 1))
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 < 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE c1 <= 100 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE c1 <= 100")
+
+        # test logging of slow queries with restriction in both partition and first clustering key prefix
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 > 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 < 100",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 >= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 <= 100",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 <= 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k IN (0) AND c1 > 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 > 0")
+
+        # test logging of slow queries with restriction in both partition and second clustering key prefix
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 = 0 AND c2 > 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 = 0 AND c2 > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 = 0 AND c2 < 100",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 = 0 AND c2 < 100")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 = 0 AND c2 >= 0",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 = 0 AND c2 >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE k = 0 AND c1 = 0 AND c2 <= 100",
+                                      logged_query="SELECT \* FROM ks.{} WHERE k = 0 AND c1 = 0 AND c2 <= 100")
+
+        # test logging of slow queries with restriciton on regular column
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v = 1 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v = 1")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v < 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v < 2")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE v <= 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE v <= 2")
+
+        # test logging of slow queries with restriciton on static column
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE s = 1 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE s = 1")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE s > 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE s > 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE s < 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE s < 2")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE s >= 0 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE s >= 0")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT * FROM {} WHERE s <= 2 ALLOW FILTERING",
+                                      logged_query="SELECT \* FROM ks.{} WHERE s <= 2")
+
+        # test logging of slow queries with column selections
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT s FROM {}",
+                                      logged_query="SELECT s FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT v FROM {}",
+                                      logged_query="SELECT v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT lt FROM {}",
+                                      logged_query="SELECT lt FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT st FROM {}",
+                                      logged_query="SELECT st FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT mp FROM {}",
+                                      logged_query="SELECT mp FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT \"Escaped_Name\" FROM {}",
+                                      logged_query="SELECT \"Escaped_Name\" FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT v,s,st FROM {}",
+                                      logged_query="SELECT s, st, v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k,v,s,st FROM {}",
+                                      logged_query="SELECT s, st, v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k,c1,v,st FROM {}",
+                                      logged_query="SELECT st, v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k,c2,v,st FROM {}",
+                                      logged_query="SELECT st, v FROM ks.{}")
+        TestCQLSlowQuery._assert_logs(node, session, table,
+                                      query="SELECT k,c1,c2,v,st FROM {}",
+                                      logged_query="SELECT st, v FROM ks.{}")
+
+        # test logging of slow queries with primary key-only column selections
+        logged_query = "SELECT \* FROM ks.{}"
+        TestCQLSlowQuery._assert_logs(node, session, table, query="SELECT k FROM {}", logged_query=logged_query)
+        TestCQLSlowQuery._assert_logs(node, session, table, query="SELECT c1 FROM {}", logged_query=logged_query)
+        TestCQLSlowQuery._assert_logs(node, session, table, query="SELECT c2 FROM {}", logged_query=logged_query)
+        TestCQLSlowQuery._assert_logs(node, session, table, query="SELECT k,c1 FROM {}", logged_query=logged_query)
+        TestCQLSlowQuery._assert_logs(node, session, table, query="SELECT k,c1,c2 FROM {}", logged_query=logged_query)
+
+        # test logging of slow queries with column sub-selections (only supported since 4.0)
+        if node.cluster.version() >= '4.0':
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT st[0] FROM {}",
+                                          logged_query="SELECT st\[0\] FROM ks.{}")
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT mp[0] FROM {}",
+                                          logged_query="SELECT mp\[0\] FROM ks.{}")
+            TestCQLSlowQuery._assert_logs(node, session, table,
+                                          query="SELECT k,c1,v,st[0],mp[1] FROM {}",
+                                          logged_query="SELECT mp\[1\], st\[0\], v FROM ks.{}")
+
+    @staticmethod
+    def _assert_logs(node, session, table, query, logged_query):
+
+        # only check debug logs because at INFO level the no-spam logger has unpredictable results
+        mark = node.mark_log(filename='debug.log')
+
+        session.execute(SimpleStatement(query.format(table),
+                                        consistency_level=ConsistencyLevel.ONE,
+                                        retry_policy=FallthroughRetryPolicy()))
+
+        node.watch_log_for(["operations were slow", logged_query.format(table)],
+                           from_mark=mark, filename='debug.log', timeout=60)
+
+    @staticmethod
+    def _check_logs(node, pattern, filename, num_expected):
         ret = node.grep_log(pattern, filename=filename)
         assert_length_equal(ret, num_expected)
 
@@ -1230,7 +1529,7 @@ class TestLWTWithCQL(Tester):
     def fixture_post_initialize_cluster(self, fixture_dtest_setup):
         cluster = fixture_dtest_setup.cluster
         cluster.populate(3)
-        cluster.start(wait_for_binary_proto=True)
+        cluster.start()
 
     def get_lwttester_session(self):
         node1 = self.cluster.nodelist()[0]