twister: improve logging of cmake commands

With verbose output enabled, twister logs the cmake arguments as a
python array whenever it invokes cmake to generate a build system.

This is clunky output for manual reproduction, because it forces the
developer to manually join the arguments together for consumption by
the shell.

As an enhancement for this use case, use the standard library
shlex.join() function to produce a string that can be copy/pasted
directly into the shell on POSIX platforms.

We should use this function instead of str.join, because it correctly
handles things like shell quoting for options with spaces in them.

This function is not available on Windows, so we fall back on behavior
that is similar to the old one there.

The main difference on Windows is that the output now includes the
path to cmake as well, and not just its arguments. (This is the same
on POSIX, and is intended to help debug if multiple cmakes are
installed on the same machine.)

We are running cmake from a couple of different places, so doing this
cleanly requires adding a shared module with the platform abstraction.

Signed-off-by: Martí Bolívar <[email protected]>

Author: mbolivar-nordic

scripts/pylib/twister/twisterlib/environment.py

@@ -18,6 +18,7 @@
 logger.setLevel(logging.DEBUG)
 
 from twisterlib.error import TwisterRuntimeError
+from twisterlib.log_helper import log_command
 
 ZEPHYR_BASE = os.getenv("ZEPHYR_BASE")
 if not ZEPHYR_BASE:
@@ -705,19 +706,20 @@ def check_zephyr_version(self):
 
     @staticmethod
     def run_cmake_script(args=[]):
+        script = os.fspath(args[0])
 
-        logger.debug("Running cmake script %s" % (args[0]))
+        logger.debug("Running cmake script %s", script)
 
         cmake_args = ["-D{}".format(a.replace('"', '')) for a in args[1:]]
-        cmake_args.extend(['-P', args[0]])
+        cmake_args.extend(['-P', script])
 
-        logger.debug("Calling cmake with arguments: {}".format(cmake_args))
         cmake = shutil.which('cmake')
         if not cmake:
             msg = "Unable to find `cmake` in path"
             logger.error(msg)
             raise Exception(msg)
         cmd = [cmake] + cmake_args
+        log_command(logger, "Calling cmake", cmd)
 
         kwargs = dict()
         kwargs['stdout'] = subprocess.PIPE

scripts/pylib/twister/twisterlib/log_helper.py

@@ -0,0 +1,27 @@
+# Copyright (c) 2022 Nordic Semiconductor ASA
+# SPDX-License-Identifier: Apache-2.0
+
+'''
+Common code used when logging that is needed by multiple modules.
+'''
+
+import platform
+import shlex
+
+_WINDOWS = (platform.system() == 'Windows')
+
+def log_command(logger, msg, args):
+    '''Platform-independent helper for logging subprocess invocations.
+    Will log a command string that can be copy/pasted into a POSIX
+    shell on POSIX platforms. This is not available on Windows, so
+    the entire args array is logged instead.
+
+    :param logger: logging.Logger to use
+    :param msg: message to associate with the command
+    :param args: argument list as passed to subprocess module
+    '''
+    msg = f'{msg}: %s'
+    if _WINDOWS:
+        logger.debug(msg, str(args))
+    else:
+        logger.debug(msg, shlex.join(args))

scripts/pylib/twister/twisterlib/runner.py

@@ -19,6 +19,7 @@
 from multiprocessing.managers import BaseManager
 from twisterlib.cmakecache import CMakeCache
 from twisterlib.environment import canonical_zephyr_base
+from twisterlib.log_helper import log_command
 
 logger = logging.getLogger('twister')
 logger.setLevel(logging.DEBUG)
@@ -262,12 +263,12 @@ def run_cmake(self, args=""):
         cmake_opts = ['-DBOARD={}'.format(self.platform.name)]
         cmake_args.extend(cmake_opts)
 
-
-        logger.debug("Calling cmake with arguments: {}".format(cmake_args))
         cmake = shutil.which('cmake')
         cmd = [cmake] + cmake_args
         kwargs = dict()
 
+        log_command(logger, "Calling cmake", cmd)
+
         if self.capture_output:
             kwargs['stdout'] = subprocess.PIPE
             # CMake sends the output of message() to stderr unless it's STATUS