`test_authentication.py` test suite is failing on setup with `ccmlib.node.TimeoutError` error, on scylla ver. 3.28.2 and 3.29.3

tests/integration/standard/test_authentication.py、特に setup_module() と、tests/integration/init.py:start_cluster_wait_for_up() から始めます。Scylla 3.28.2 と 3.29.3 で失敗を再現し、その後 node1 の system.log とリンクされた Argus の実行を調べて、起動が期待されるログパターンに到達しない理由を特定します。認証のセットアップが完了し、テストスイートがパスすれば完了です。

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