test_authentication.py test suite is failing on setup with ccmlib.node.TimeoutError error, on scylla ver. 3.28.2 and 3.29.3 #92
Description
test_authentication.py test suite is failing on test setup when starting scylla, with the following stacktrace:
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/node.py:500: TimeoutError
15:38:49
15:38:49 During handling of the above exception, another exception occurred:
15:38:49
15:38:49 def setup_module():
15:38:49 if CASSANDRA_IP.startswith("127.0.0.") and not USE_CASS_EXTERNAL:
15:38:49 use_singledc(start=False)
15:38:49 ccm_cluster = get_cluster()
15:38:49 ccm_cluster.stop()
15:38:49 config_options = {'authenticator': 'PasswordAuthenticator',
15:38:49 'authorizer': 'CassandraAuthorizer'}
15:38:49 ccm_cluster.set_configuration_options(config_options)
15:38:49 log.debug("Starting ccm test cluster with %s", config_options)
15:38:49 > start_cluster_wait_for_up(ccm_cluster)
15:38:49
15:38:49 tests/integration/standard/test_authentication.py:44:
15:38:49 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15:38:49 tests/integration/__init__.py:504: in start_cluster_wait_for_up
15:38:49 cluster.start(wait_for_binary_proto=True, wait_other_notice=True)
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/scylla_cluster.py:175: in start
15:38:49 started = self.start_nodes(**kwargs)
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/scylla_cluster.py:140: in start_nodes
15:38:49 p = node.start(update_pid=False, jvm_args=jvm_args,
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/scylla_node.py:768: in start
15:38:49 scylla_process = self._start_scylla(args=args, marks=marks, update_pid=update_pid,
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/scylla_node.py:409: in _start_scylla
15:38:49 self.wait_for_starting(from_mark=self.mark, timeout=t)
15:38:49 venv/scylla/3.28.2/lib/python3.9/site-packages/ccmlib/scylla_node.py:338: in wait_for_starting
15:38:49 if not self.watch_log_for(f"{starting_message}|{bootstrap_message}|{resharding_message}", from_mark=from_mark, timeout=timeout, process=process):
15:38:49 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15:38:49
15:38:49 self = <ccmlib.scylla_node.ScyllaNode object at 0x7f6369e2ff70>
15:38:49 exprs = 'Starting listening for CQL clients|storage_service .* Starting to bootstrap|(compaction|database) -.*Resharding'
15:38:49 from_mark = 139067, timeout = 420
15:38:49 process = <Popen: returncode: None args: ['/jenkins/workspace/enterprise-2024.1/driver...>
15:38:49 verbose = False, filename = 'system.log', polling_interval = 0.01
15:38:49
15:38:49 def watch_log_for(self, exprs, from_mark=None, timeout=600, process=None, verbose=False, filename='system.log', polling_interval=0.01):
15:38:49 """
15:38:49 Watch the log until all (regular) expression are found or the timeout is reached.
15:38:49 On successful completion, a list of pairs (line matched, match object) is returned.
15:38:49 If the timeout expired before matching all expressions in `exprs`,
15:38:49 a TimeoutError is raised.
15:38:49 The `polling_interval` determines how long we sleep when
15:38:49 reaching the end of file before attempting to read the next line.
15:38:49 """
15:38:49 deadline = time.time() + timeout
15:38:49 tofind = [exprs] if isinstance(exprs, str) else exprs
15:38:49 tofind = [re.compile(e) for e in tofind]
15:38:49 matchings = []
15:38:49 reads = ""
15:38:49 if len(tofind) == 0:
15:38:49 return None
15:38:49
15:38:49 log_file = os.path.join(self.get_path(), 'logs', filename)
15:38:49 while not os.path.exists(log_file):
15:38:49 time.sleep(.1)
15:38:49 if process:
15:38:49 process.poll()
15:38:49 if process.returncode is not None:
15:38:49 self.print_process_output(self.name, process, verbose)
15:38:49 if process.returncode != 0:
15:38:49 raise RuntimeError() # Shouldn't reuse RuntimeError but I'm lazy
15:38:49
15:38:49 with open(log_file) as f:
15:38:49 if from_mark:
15:38:49 f.seek(from_mark)
15:38:49
15:38:49 while True:
15:38:49 # First, if we have a process to check, then check it.
15:38:49 # Skip on Windows - stdout/stderr is cassandra.bat
15:38:49 if not common.is_win():
15:38:49 if process:
15:38:49 process.poll()
15:38:49 if process.returncode is not None:
15:38:49 self.print_process_output(self.name, process, verbose)
15:38:49 if process.returncode != 0:
15:38:49 raise RuntimeError() # Shouldn't reuse RuntimeError but I'm lazy
15:38:49
15:38:49 line = f.readline()
15:38:49 if line:
15:38:49 reads = reads + line
15:38:49 for e in tofind:
15:38:49 m = e.search(line)
15:38:49 if m:
15:38:49 matchings.append((line, m))
15:38:49
15:38:49 # This is bogus! - One should not modify the list from inside the loop which iterates on
15:38:49 # that list.
15:38:49 # However since we are going to break from the loop a few lines below that should be ok.
15:38:49 tofind.remove(e)
15:38:49
15:38:49 if len(tofind) == 0:
15:38:49 return matchings[0] if isinstance(exprs, str) else matchings
15:38:49 break
15:38:49 else:
15:38:49 # yep, it's ugly
15:38:49 # FIXME: consider using inotify with IN_MODIFY to monitor the file
15:38:49 time.sleep(polling_interval)
15:38:49 if time.time() > deadline:
15:38:49 > raise TimeoutError(time.strftime("%d %b %Y %H:%M:%S", time.gmtime()) + " [" + self.name + "] Missing: " + str(
15:38:49 [e.pattern for e in tofind]) + ":\n" + reads[:50] + f".....\nSee {filename} for remainder")
15:38:49 E ccmlib.node.TimeoutError: 03 Aug 2025 13:14:26 [node1] Missing: ['Starting listening for CQL clients|storage_service .* Starting to bootstrap|(compaction|database) -.*Resharding']:
15:38:49 E /bin/bash: warning: setlocale: LC_ALL: cannot chan.....
15:38:49 E See system.log for remainder
Failing tests in argus: https://argus.scylladb.com/tests/driver-matrix-tests/67313434-6e1c-42c1-8b8f-4c55e16b17fc/tests