Improve debug logging (#8325)

Update the bootstrap and helpers script to add verbose logging to help
troubleshoot the code path taken.

Also, update the build-using-self to add command line option to enable
xctest/swift-testing tests.

Author: bkhouri

Utilities/bootstrap

@@ -53,9 +53,19 @@ else:
 class BinaryNotFound(BaseException):
 
     def __init__(self, *, tool: str, path: pathlib.Path):
-        super().__init__("Unable to find {tool} source directory at {path}")
+        super().__init__(f"Unable to find {tool} source directory at {path}")
 
+def log_entry_exit(func):
+    def wrapper(*args, **kwargs):
+        logging.debug("Starting call to %s ...", func.__name__)
+        try:
+            return func(*args, **kwargs)
+        finally:
+            logging.debug("Done call to %s ...", func.__name__)
 
+    return wrapper
+
+@log_entry_exit
 def main():
     parser = argparse.ArgumentParser(description="""
         This script will build a bootstrapped copy of the Swift Package Manager, and optionally perform extra
@@ -95,6 +105,7 @@ def main():
 # Argument parsing
 # -----------------------------------------------------------
 
+@log_entry_exit
 def add_global_args(parser):
     """Configures the parser with the arguments necessary for all actions."""
     parser.add_argument(
@@ -111,6 +122,7 @@ def add_global_args(parser):
         action="store_true",
         help="whether to always reconfigure cmake")
 
+@log_entry_exit
 def add_build_args(parser):
     """Configures the parser with the arguments necessary for build-related actions."""
     add_global_args(parser)
@@ -187,6 +199,7 @@ def add_build_args(parser):
         "--cross-compile-config",
         help="Swift flags to cross-compile SwiftPM with itself")
 
+@log_entry_exit
 def add_test_args(parser):
     """Configures the parser with the arguments necessary for the test action."""
     add_build_args(parser)
@@ -206,6 +219,7 @@ def add_test_args(parser):
         help="whether to skip tests with the integrated driver",
         default=True)
 
+@log_entry_exit
 def parse_global_args(args):
     """Parses and cleans arguments necessary for all actions."""
     # Test if 'build_dirs' and 'source_dirs' exist, and initialise them only if not.
@@ -236,6 +250,7 @@ def parse_global_args(args):
     else:
         args.sysroot = None
 
+@log_entry_exit
 def parse_build_args(args):
     """Parses and cleans arguments necessary for build-related actions."""
     parse_global_args(args)
@@ -250,6 +265,8 @@ def parse_build_args(args):
         args.build_dirs["llbuild"] = os.path.abspath(args.llbuild_build_dir)
 
     args.swiftc_path = get_swiftc_path(args)
+    logging.debug("Returned value of get_swiftc_path(args): %r", get_swiftc_path(args))
+    logging.debug("Settings args.swiftc_path to %r", args.swiftc_path)
     args.clang_path = get_tool_path(args, "clang")
     args.clangxx_path = get_tool_path(args, "clang++")
     if not args.skip_cmake_bootstrap:
@@ -276,10 +293,12 @@ def parse_build_args(args):
     args.bootstrap = not args.skip_cmake_bootstrap or \
                      not os.path.exists(os.path.join(os.path.split(args.swiftc_path)[0], "swift-build"))
 
+@log_entry_exit
 def parse_test_args(args):
     """Parses and cleans arguments necessary for the test action."""
     parse_build_args(args)
 
+@log_entry_exit
 def get_swiftc_path(args):
     """Returns the path to the Swift compiler."""
     logging.debug("Getting path to swiftc...")
@@ -307,11 +326,12 @@ def get_swiftc_path(args):
 
     logging.debug("swiftc_path set to %r", swiftc_path)
     if os.path.exists(swiftc_path):
-        logging.debug("swiftc_path exists.. returning...")
+        logging.debug("swiftc_path exists.. returning %r...", swiftc_path)
         return swiftc_path
     logging.error("unable to find swiftc at %s", swiftc_path)
     raise BinaryNotFound(tool="swiftc", path=swiftc_path)
 
+@log_entry_exit
 def get_tool_path(args, tool):
     """Returns the path to the specified tool."""
     logging.debug("Searching for %s tool", tool)
@@ -327,6 +347,7 @@ def get_tool_path(args, tool):
     else:
         return call_output(["which", tool], verbose=args.verbose)
 
+@log_entry_exit
 def get_build_target(args, cross_compile=False):
     """Returns the target-triple of the current machine or for cross-compilation."""
     try:
@@ -379,13 +400,15 @@ def get_unversioned_build_target(args, cross_compile=False):
 # Actions
 # -----------------------------------------------------------
 
+@log_entry_exit
 def clean(args):
     """Cleans the build artifacts."""
     logging.info("Cleaning")
     parse_global_args(args)
 
     call(["rm", "-rf", args.build_dir], verbose=args.verbose)
 
+@log_entry_exit
 def build(args):
     """Builds SwiftPM using a two-step process: first using CMake, then with itself."""
     parse_build_args(args)
@@ -423,6 +446,7 @@ def build(args):
 
     build_swiftpm_with_swiftpm(args,integrated_swift_driver=False)
 
+@log_entry_exit
 def test(args):
     """Builds SwiftPM, then tests itself."""
     build(args)
@@ -456,6 +480,7 @@ def test(args):
         integratedDriverCmd.append("BuildTests;FunctionalTests")
     call_swiftpm(args, integratedDriverCmd)
 
+@log_entry_exit
 def install(args):
     """Builds SwiftPM, then installs its build products."""
     build(args)
@@ -493,6 +518,7 @@ def install(args):
         install_dylib(args, "SwiftPMDataModel", args.libswiftpmdatamodel_install_dir, libswiftpmdatamodel_modules)
 
 # Installs the SwiftPM tools and runtime support libraries.
+@log_entry_exit
 def install_swiftpm(prefix, args):
     # Install the swift-package-manager tool and create symlinks to it.
     cli_tool_dest = os.path.join(prefix, "bin")
@@ -520,6 +546,7 @@ def install_swiftpm(prefix, args):
 
 
 # Helper function that installs a dynamic library and a set of modules to a particular directory.
+@log_entry_exit
 def install_dylib(args, library_name, install_dir, module_names):
     # Install the dynamic library itself.
     install_binary(args, g_shared_lib_prefix + library_name + g_shared_lib_suffix, install_dir)
@@ -541,6 +568,7 @@ def install_dylib(args, library_name, install_dir, module_names):
 
 
 # Helper function that installs a single built artifact to a particular directory. The source may be either a file or a directory.
+@log_entry_exit
 def install_binary(args, binary, destination, destination_is_directory=True, ignored_patterns=[], subpath=None):
     if subpath:
         basepath = os.path.join(args.bin_dir, subpath)
@@ -549,6 +577,7 @@ def install_binary(args, binary, destination, destination_is_directory=True, ign
     src = os.path.join(basepath, binary)
     install_file(args, src, destination, destination_is_directory=destination_is_directory, ignored_patterns=ignored_patterns)
 
+@log_entry_exit
 def install_file(args, src, destination, destination_is_directory=True, ignored_patterns=[]):
     if destination_is_directory:
         dest = os.path.join(destination, os.path.basename(src))
@@ -566,6 +595,7 @@ def install_file(args, src, destination, destination_is_directory=True, ignored_
 # Build functions
 # -----------------------------------------------------------
 
+@log_entry_exit
 def build_with_cmake(args, cmake_args, ninja_args, source_path, build_dir, cmake_env = []):
     """Runs CMake if needed, then builds with Ninja."""
     cache_path = os.path.join(build_dir, "CMakeCache.txt")
@@ -605,6 +635,7 @@ def build_with_cmake(args, cmake_args, ninja_args, source_path, build_dir, cmake
 
     call(ninja_cmd + ninja_args, cwd=build_dir, verbose=args.verbose)
 
+@log_entry_exit
 def build_llbuild(args):
     """Builds LLBuild using CMake."""
     logging.info("Building llbuild")
@@ -637,6 +668,7 @@ def build_llbuild(args):
     args.source_dirs["llbuild"] = get_llbuild_source_path(args)
     build_with_cmake(args, flags, [], args.source_dirs["llbuild"], args.build_dirs["llbuild"], cmake_env=cmake_env)
 
+@log_entry_exit
 def build_dependency(args, target_name, common_cmake_flags = [], non_darwin_cmake_flags = []):
     logging.info("Building dependency %s", target_name)
     args.build_dirs[target_name] = os.path.join(args.target_dir, target_name)
@@ -650,19 +682,22 @@ def build_dependency(args, target_name, common_cmake_flags = [], non_darwin_cmak
 
     build_with_cmake(args, cmake_flags, [], args.source_dirs[target_name], args.build_dirs[target_name])
 
+@log_entry_exit
 def add_rpath_for_cmake_build(args, rpath):
     "Adds the given rpath to the CMake-built swift-bootstrap"
     swift_build = os.path.join(args.bootstrap_dir, "bin/swift-bootstrap")
     add_rpath_cmd = ["install_name_tool", "-add_rpath", rpath, swift_build]
     logging.info(' '.join(add_rpath_cmd))
     subprocess.call(add_rpath_cmd, stderr=subprocess.PIPE, env=os.environ)
 
+@log_entry_exit
 def get_swift_backdeploy_library_paths(args):
     if platform.system() == 'Darwin':
         return ['/usr/lib/swift']
     else:
         return []
 
+@log_entry_exit
 def build_swiftpm_with_cmake(args):
     """Builds SwiftPM using CMake."""
     logging.info("Building SwiftPM (with CMake)")
@@ -702,6 +737,7 @@ def build_swiftpm_with_cmake(args):
         for lib_path in get_swift_backdeploy_library_paths(args):
             add_rpath_for_cmake_build(args, lib_path)
 
+@log_entry_exit
 def build_swiftpm_with_swiftpm(args, integrated_swift_driver):
     """Builds SwiftPM using the version of SwiftPM built with CMake."""
 
@@ -745,6 +781,7 @@ def build_swiftpm_with_swiftpm(args, integrated_swift_driver):
 
     symlink_force(os.path.join(args.bootstrap_dir, "pm"), os.path.join(lib_dir, "pm"))
 
+@log_entry_exit
 def call_swiftpm(args, cmd, cwd=None):
     """Calls a SwiftPM binary with the necessary environment variables and flags."""
     logging.info("function args: %r, cmd: %r, cwd: %r", args, cmd, cwd)
@@ -773,16 +810,19 @@ def call_swiftpm(args, cmd, cwd=None):
 # Build-related helper functions
 # -----------------------------------------------------------
 
+@log_entry_exit
 def get_dispatch_cmake_arg(args):
     """Returns the CMake argument to the Dispatch configuration to use for building SwiftPM."""
     dispatch_dir = os.path.join(args.dispatch_build_dir, "cmake/modules")
     return "-Ddispatch_DIR=" + dispatch_dir
 
+@log_entry_exit
 def get_foundation_cmake_arg(args):
     """Returns the CMake argument to the Foundation configuration to use for building SwiftPM."""
     foundation_dir = os.path.join(args.foundation_build_dir, "cmake/modules")
     return "-DFoundation_DIR=" + foundation_dir
 
+@log_entry_exit
 def get_llbuild_cmake_arg(args):
     """Returns the CMake argument to the LLBuild framework/binary to use for building SwiftPM."""
     if args.llbuild_link_framework:
@@ -791,6 +831,7 @@ def get_llbuild_cmake_arg(args):
         llbuild_dir = os.path.join(args.build_dirs["llbuild"], "cmake/modules")
         return "-DLLBuild_DIR=" + llbuild_dir
 
+@log_entry_exit
 def get_llbuild_source_path(args):
     """Returns the path to the LLBuild source folder."""
     llbuild_path = os.path.join(args.project_root, "..", "llbuild")
@@ -800,6 +841,7 @@ def get_llbuild_source_path(args):
     logging.error("unable to find llbuild source directory at %s", llbuild_path)
     raise BinaryNotFound(tool="llbuild", path=llbuild_path)
 
+@log_entry_exit
 def get_swiftpm_env_cmd(args):
     """Returns the environment variable command to run SwiftPM binaries."""
     env_cmd = ["env"]
@@ -846,6 +888,7 @@ def get_swiftpm_env_cmd(args):
     ]
     return env_cmd
 
+@log_entry_exit
 def get_swiftpm_flags(args):
     """Returns the flags to run SwiftPM binaries."""
     build_flags = [

Utilities/build-using-self

@@ -68,7 +68,14 @@ def get_arguments() -> argparse.Namespace:
         choices=[e.value for e in Configuration],
         help="The configuraiton to use.",
     )
-
+    parser.add_argument(
+        "--enable-swift-testing",
+        action="store_true",
+    )
+    parser.add_argument(
+        "--enable-xctest",
+        action="store_true",
+    )
     args = parser.parse_args()
     return args
 
@@ -147,8 +154,10 @@ def main() -> None:
         call(
             shlex.split(f"swift build --configuration {args.config}"),
         )
+        swift_testing_arg= "--enable-swift-testing" if args.enable_swift_testing else ""
+        xctest_arg= "--enable-xctest" if args.enable_swift_testing else ""
         call(
-            shlex.split(f"swift test --configuration {args.config} --parallel"),
+            shlex.split(f"swift test --configuration {args.config} --parallel {swift_testing_arg} {xctest_arg}"),
         )
 
     with change_directory(REPO_ROOT_PATH / "IntegrationTests"):

Utilities/helpers.py

@@ -71,8 +71,22 @@ def call(cmd, cwd=None, verbose=False):
     except subprocess.CalledProcessError as cpe:
         logging.debug("executing command >>> %r with cwd %s", " ".join([str(c) for c in cmd]), cwd)
         logging.error(
-            "Process failure: %s\n[---- START OUTPUT ----]\n%s\n[---- END OUTPUT ----]",
+            "\n".join([
+                "Process failure with return code %d: %s",
+                "[---- START stdout ----]",
+                "%s",
+                "[---- END stdout ----]",
+                "[---- START stderr ----]",
+                "%s",
+                "[---- END stderr ----]",
+                "[---- START OUTPUT ----]",
+                "%s",
+                "[---- END OUTPUT ----]",
+            ]),
+            cpe.returncode,
             str(cpe),
+            cpe.stdout,
+            cpe.stderr,
             cpe.output,
         )
         raise cpe
@@ -93,8 +107,22 @@ def call_output(cmd, cwd=None, stderr=False, verbose=False):
     except subprocess.CalledProcessError as cpe:
         logging.debug("executing command >>> %r with cwd %s", " ".join([str(c) for c in cmd]), cwd)
         logging.error(
-            "%s\n[---- START OUTPUT ----]\n%s\n[---- END OUTPUT ----]",
+            "\n".join([
+                "Process failure with return code %d: %s",
+                "[---- START stdout ----]",
+                "%s",
+                "[---- END stdout ----]",
+                "[---- START stderr ----]",
+                "%s",
+                "[---- END stderr ----]",
+                "[---- START OUTPUT ----]",
+                "%s",
+                "[---- END OUTPUT ----]",
+            ]),
+            cpe.returncode,
             str(cpe),
+            cpe.stdout,
+            cpe.stderr,
             cpe.output,
         )
         raise cpe