Configure create_package_and_install to be more responsive to logging settings (#42862)

* update build_package function (heavily used by create_package_and_install) to be much less verbose by default. We do not see to see
  all build output for every package when it's just standard  assembly. we have verify_sdist and verify_whl, and beyond that devs should validate
  the contents of their packages.
* in error cases, we should still see error output, but otherwise, users will have to set LOG_LEVEL environment variable at runtime to see the raw build logs

---------

Co-authored-by: Copilot <[email protected]>
Co-authored-by: McCoy Patiño <[email protected]>

Author: 3 people

eng/tools/azure-sdk-tools/ci_tools/build.py

@@ -8,7 +8,7 @@
 from ci_tools.variables import DEFAULT_BUILD_ID, str_to_bool, discover_repo_root, get_artifact_directory
 from ci_tools.versioning.version_shared import set_version_py, set_dev_classifier
 from ci_tools.versioning.version_set_dev import get_dev_version, format_build_id
-
+from ci_tools.logging import logger, configure_logging, run_logged
 
 def build_package() -> None:
     parser = argparse.ArgumentParser(
@@ -39,6 +39,7 @@ def build_package() -> None:
     )
 
     args = parser.parse_args()
+    configure_logging(args)
 
     target_package = ParsedSetup.from_path(args.package_folder)
     artifact_directory = get_artifact_directory(args.distribution_directory)
@@ -146,6 +147,8 @@ def build() -> None:
 
     args = parser.parse_args()
 
+    configure_logging(args)
+
     repo_root = discover_repo_root(args.repo)
 
     if args.service and args.service != "auto":
@@ -154,7 +157,7 @@ def build() -> None:
     else:
         target_dir = repo_root
 
-    logging.debug(
+    logger.debug(
         f"Searching for packages starting from {target_dir} with glob string {args.glob_string} and package filter {args.package_filter_string}"
     )
 
@@ -202,7 +205,7 @@ def build_packages(
     enable_wheel: bool = True,
     enable_sdist: bool = True
 ):
-    logging.log(level=logging.INFO, msg=f"Generating {targeted_packages} using python{sys.version}")
+    logger.info(f"Generating {targeted_packages} using python{sys.version}")
 
     for package_root in targeted_packages:
         setup_parsed = ParsedSetup.from_path(package_root)
@@ -218,7 +221,7 @@ def build_packages(
 
             new_version = get_dev_version(setup_parsed.version, build_id)
 
-            logging.log(level=logging.DEBUG, msg=f"{setup_parsed.name}: {setup_parsed.version} -> {new_version}")
+            logger.debug(f"{setup_parsed.name}: {setup_parsed.version} -> {new_version}")
 
             set_version_py(setup_parsed.setup_filename, new_version)
             set_dev_classifier(setup_parsed.setup_filename, new_version)
@@ -237,6 +240,8 @@ def create_package(
     dist = get_artifact_directory(dest_folder)
     setup_parsed = ParsedSetup.from_path(setup_directory_or_file)
 
+    should_log_build_output = logger.getEffectiveLevel() <= logging.DEBUG
+
     if setup_parsed.is_pyproject:
         # when building with pyproject, we will use `python -m build` to build the package
         # -n argument will not use an isolated environment, which means the current environment must have all the dependencies of the package installed, to successfully
@@ -247,14 +252,14 @@ def create_package(
         # we assume the presence of `wheel`, `build`, `setuptools>=61.0.0`
         pip_output = get_pip_list_output(sys.executable)
         necessary_install_requirements = [req for req in setup_parsed.requires if parse_require(req).name not in pip_output.keys()]
-        run([sys.executable, "-m", "pip", "install", *necessary_install_requirements], cwd=setup_parsed.folder)
-        run([sys.executable, "-m", "build", f"-n{'s' if enable_sdist else ''}{'w' if enable_wheel else ''}", "-o", dist], cwd=setup_parsed.folder, check=True)
+        run_logged([sys.executable, "-m", "pip", "install", *necessary_install_requirements], cwd=setup_parsed.folder, check=False, should_stream_to_console=should_log_build_output)
+        run_logged([sys.executable, "-m", "build", f"-n{'s' if enable_sdist else ''}{'w' if enable_wheel else ''}", "-o", dist], cwd=setup_parsed.folder, check=True, should_stream_to_console=should_log_build_output)
     else:
         if enable_wheel:
             if setup_parsed.ext_modules:
-                run([sys.executable, "-m", "cibuildwheel", "--output-dir", dist], cwd=setup_parsed.folder, check=True)
+                run_logged([sys.executable, "-m", "cibuildwheel", "--output-dir", dist], cwd=setup_parsed.folder, check=True, should_stream_to_console=should_log_build_output)
             else:
-                run([sys.executable, "setup.py", "bdist_wheel", "-d", dist], cwd=setup_parsed.folder, check=True)
+                run_logged([sys.executable, "setup.py", "bdist_wheel", "-d", dist], cwd=setup_parsed.folder, check=True, should_stream_to_console=should_log_build_output)
 
         if enable_sdist:
-            run([sys.executable, "setup.py", "sdist", "-d", dist], cwd=setup_parsed.folder, check=True)
+            run_logged([sys.executable, "setup.py", "sdist", "-d", dist], cwd=setup_parsed.folder, check=True, should_stream_to_console=should_log_build_output)

eng/tools/azure-sdk-tools/ci_tools/functions.py

@@ -13,6 +13,7 @@
 from ci_tools.variables import discover_repo_root, DEV_BUILD_IDENTIFIER, str_to_bool
 from ci_tools.parsing import ParsedSetup, get_config_setting, get_pyproject
 from pypi_tools.pypi import PyPIClient
+from ci_tools.logging import logger
 
 import os, sys, platform, glob, re, logging
 from typing import List, Any, Optional, Tuple
@@ -222,25 +223,25 @@ def discover_targeted_packages(
 
     # glob the starting package set
     collected_packages = glob_packages(glob_string, target_root_dir)
-    logging.info(
+    logger.debug(
         f'Results for glob_string "{glob_string}" and root directory "{target_root_dir}" are: {collected_packages}'
     )
 
     # apply the additional contains filter
     collected_packages = [pkg for pkg in collected_packages if additional_contains_filter in pkg]
-    logging.info(f'Results after additional contains filter: "{additional_contains_filter}" {collected_packages}')
+    logger.debug(f'Results after additional contains filter: "{additional_contains_filter}" {collected_packages}')
 
     # filter for compatibility, this means excluding a package that doesn't support py36 when we are running a py36 executable
     if compatibility_filter:
         collected_packages = apply_compatibility_filter(collected_packages)
-        logging.info(f"Results after compatibility filter: {collected_packages}")
+        logger.debug(f"Results after compatibility filter: {collected_packages}")
 
     if not include_inactive:
         collected_packages = apply_inactive_filter(collected_packages)
 
     # Apply filter based on filter type. for e.g. Docs, Regression, Management
     collected_packages = apply_business_filter(collected_packages, filter_type)
-    logging.info(f"Results after business filter: {collected_packages}")
+    logger.debug(f"Results after business filter: {collected_packages}")
 
     return sorted(collected_packages)
 
@@ -1037,6 +1038,7 @@ def get_pip_command(python_exe: Optional[str] = None) -> List[str]:
         return [python_exe if python_exe else sys.executable, "-m", "pip"]
 
 
+
 def is_error_code_5_allowed(target_pkg: str, pkg_name: str):
     """
     Determine if error code 5 (no pytests run) is allowed for the given package.

eng/tools/azure-sdk-tools/ci_tools/logging/__init__.py

@@ -1,13 +1,14 @@
-import logging
-from logging import Logger
-from ci_tools.variables import get_log_directory, in_ci
 import os
 import datetime
-from subprocess import run
+import subprocess
 import argparse
+import logging
 
-LOGLEVEL = getattr(logging, os.environ.get("LOGLEVEL", "INFO").upper())
+from logging import Logger
 
+from ci_tools.variables import get_log_directory, in_ci
+
+LOGLEVEL = getattr(logging, os.environ.get("LOGLEVEL", "INFO").upper())
 logger = logging.getLogger("azure-sdk-tools")
 
 def configure_logging(
@@ -73,11 +74,43 @@ def get_log_file(prefix: str = "") -> str:
     return logfile
 
 
-def run_logged(*args, prefix="", **kwargs):
+def run_logged_to_file(*args, prefix="", **kwargs):
     logfile = get_log_file(prefix)
 
     with open(logfile, "w") as log_output:
-        run(*args, **kwargs, stdout=log_output, stderr=log_output)
+        subprocess.run(*args, **kwargs, stdout=log_output, stderr=log_output)
 
 
-__all__ = ["initialize_logger", "run_logged"]
+def run_logged(cmd: list[str], cwd: str, check: bool, should_stream_to_console: bool):
+    """
+    Runs a command, logging output to subprocess.PIPE or streaming live to console based on log level.
+
+    Regardless of `should_stream_to_console`, if the command fails, the captured output will be logged.
+    """
+    try:
+        if should_stream_to_console:
+            # Stream live, no capturing
+            return subprocess.run(
+                cmd,
+                cwd=cwd,
+                check=check,
+                text=True,
+                stderr=subprocess.STDOUT
+            )
+        else:
+            # Capture merged output but don't print unless there's a failure
+            return subprocess.run(
+                cmd,
+                cwd=cwd,
+                check=check,
+                text=True,
+                stdout=subprocess.PIPE,
+                stderr=subprocess.STDOUT
+            )
+    except subprocess.CalledProcessError as e:
+        logger.error(f"Command failed: {' '.join(cmd)}")
+        if e.stdout:
+            logger.error(f"\n{e.stdout.strip()}")
+        raise
+
+__all__ = ["initialize_logger", "run_logged_to_file", "run_logged"]

eng/tools/azure-sdk-tools/ci_tools/scenario/generation.py

@@ -20,6 +20,7 @@
 from ci_tools.functions import get_package_from_repo_or_folder, find_whl, get_pip_list_output, pytest
 from .managed_virtual_env import ManagedVirtualEnv
 
+from ci_tools.logging import logger
 
 def prepare_environment(package_folder: str, venv_directory: str, env_name: str) -> str:
     """
@@ -84,7 +85,7 @@ def create_package_and_install(
                 shutil.copy(built_pkg_path, distribution_directory)
 
     if skip_install:
-        logging.info("Flag to skip install whl is passed. Skipping package installation")
+        logger.info("Flag to skip install whl is passed. Skipping package installation")
     else:
         for built_package in discovered_packages:
             if os.getenv("PREBUILT_WHEEL_DIR") is not None and not force_create:
@@ -93,21 +94,21 @@ def create_package_and_install(
                 if os.path.isfile(package_path):
                     built_pkg_path = package_path
 
-                    logging.info("Installing {w} from directory".format(w=built_package))
+                    logger.info("Installing {w} from directory".format(w=built_package))
                 # it does't exist, so we need to error out
                 else:
-                    logging.error("{w} not present in the prebuilt package directory. Exiting.".format(w=built_package))
+                    logger.error("{w} not present in the prebuilt package directory. Exiting.".format(w=built_package))
                     exit(1)
             else:
                 built_pkg_path = os.path.abspath(os.path.join(distribution_directory, built_package))
-                logging.info("Installing {w} from fresh built package.".format(w=built_package))
+                logger.info("Installing {w} from fresh built package.".format(w=built_package))
 
             if not pre_download_disabled:
                 requirements = ParsedSetup.from_path(os.path.join(os.path.abspath(target_setup))).requires
                 azure_requirements = [req.split(";")[0] for req in requirements if req.startswith("azure-")]
 
                 if azure_requirements:
-                    logging.info(
+                    logger.debug(
                         "Found {} azure requirement(s): {}".format(len(azure_requirements), azure_requirements)
                     )
 
@@ -130,7 +131,7 @@ def create_package_and_install(
                         addition_necessary = True
                         # get all installed packages
                         installed_pkgs = get_pip_list_output(python_exe)
-                        logging.info("Installed packages: {}".format(installed_pkgs))
+                        logger.debug("Installed packages: {}".format(installed_pkgs))
 
                         # parse the specifier
                         requirement = parse_require(req)
@@ -180,11 +181,11 @@ def create_package_and_install(
             commands.extend(commands_options)
 
             if work_dir and os.path.exists(work_dir):
-                logging.info("Executing command from {0}:{1}".format(work_dir, commands))
+                logger.info("Executing command from {0}:{1}".format(work_dir, commands))
                 subprocess.check_call(commands, cwd=work_dir)
             else:
                 subprocess.check_call(commands)
-            logging.info("Installed {w}".format(w=built_package))
+            logger.info("Installed {w}".format(w=built_package))
 
 
 def replace_dev_reqs(file: str, pkg_root: str, wheel_dir: Optional[str]) -> None:
@@ -238,7 +239,7 @@ def discover_packages(
         pkg = ParsedSetup.from_path(setup_path)
 
         if not packages:
-            logging.error(
+            logger.error(
                 "Package is missing in prebuilt directory {0} for package {1} and version {2}".format(
                     os.getenv("PREBUILT_WHEEL_DIR"), pkg.name, pkg.version
                 )
@@ -363,7 +364,7 @@ def build_and_discover_package(setup_path: str, dist_dir: str, target_setup: str
     ]
 
     if not in_ci():
-        logging.info("Cleaning up build directories and files")
+        logger.info("Cleaning up build directories and files")
         cleanup_build_artifacts(target_setup)
     return prebuilt_packages
 

eng/tools/azure-sdk-tools/ci_tools/versioning/version_shared.py

@@ -21,6 +21,7 @@
 from ci_tools.functions import discover_targeted_packages
 from ci_tools.parsing import ParsedSetup, get_version_py, VERSION_REGEX
 from ci_tools.variables import discover_repo_root
+from ci_tools.logging import logger
 
 from subprocess import run
 
@@ -80,7 +81,7 @@ def set_version_py(setup_path, new_version):
     version_py_location = get_version_py(setup_path)
 
     if not version_py_location:
-        logging.error("No version.py file found in {}".format(setup_path))
+        logger.error("No version.py file found in {}".format(setup_path))
         sys.exit(1)
 
     version_contents = ""

eng/tox/create_package_and_install.py

@@ -10,10 +10,8 @@
 # can be successfully tested from within a tox environment.
 
 import argparse
-import logging
-
-logging.getLogger().setLevel(logging.INFO)
 
+from ci_tools.logging import configure_logging
 from ci_tools.scenario.generation import create_package_and_install
 
 if __name__ == "__main__":
@@ -82,6 +80,10 @@
 
     args = parser.parse_args()
 
+    # none of the args will apply to logging, but the LOGLEVEL env var will
+    # so we can just pass the args object directly to configure_logging to meet the needs of the function
+    configure_logging(args)
+
     create_package_and_install(
         distribution_directory=args.distribution_directory,
         target_setup=args.target_setup,
@@ -94,4 +96,4 @@
     )
 
 
-    
+

scripts/devops_tasks/dispatch_tox.py

@@ -15,6 +15,8 @@
 import logging
 from tox_harness import prep_and_run_tox
 from ci_tools.functions import discover_targeted_packages
+from ci_tools.logging import configure_logging
+
 
 logging.getLogger().setLevel(logging.INFO)
 
@@ -114,6 +116,8 @@
 
     args = parser.parse_args()
 
+    configure_logging(args)
+
     # We need to support both CI builds of everything and individual service
     # folders. This logic allows us to do both.
     if args.service and args.service != "auto":