diff --git a/news/10705.feature.rst b/news/10705.feature.rst new file mode 100644 index 0000000000000000000000000000000000000000..7ffdeb845ba3fd94a10daecee346f81e07c34752 --- /dev/null +++ b/news/10705.feature.rst @@ -0,0 +1 @@ +Improve presentation of errors from subprocesses. diff --git a/src/pip/_internal/build_env.py b/src/pip/_internal/build_env.py index d326dc8cdb1171f2744872fdb1600d1af9f3a07f..daeb7fbc8d7c32b0d0e7c2798dc1388c4e97f74d 100644 --- a/src/pip/_internal/build_env.py +++ b/src/pip/_internal/build_env.py @@ -189,7 +189,8 @@ class BuildEnvironment: finder: "PackageFinder", requirements: Iterable[str], prefix_as_string: str, - message: str, + *, + kind: str, ) -> None: prefix = self._prefixes[prefix_as_string] assert not prefix.setup @@ -203,7 +204,7 @@ class BuildEnvironment: finder, requirements, prefix, - message, + kind=kind, ) @staticmethod @@ -212,7 +213,8 @@ class BuildEnvironment: finder: "PackageFinder", requirements: Iterable[str], prefix: _Prefix, - message: str, + *, + kind: str, ) -> None: args: List[str] = [ sys.executable, @@ -254,8 +256,13 @@ class BuildEnvironment: args.append("--") args.extend(requirements) extra_environ = {"_PIP_STANDALONE_CERT": where()} - with open_spinner(message) as spinner: - call_subprocess(args, spinner=spinner, extra_environ=extra_environ) + with open_spinner(f"Installing {kind}") as spinner: + call_subprocess( + args, + command_desc=f"pip subprocess to install {kind}", + spinner=spinner, + extra_environ=extra_environ, + ) class NoOpBuildEnvironment(BuildEnvironment): @@ -283,6 +290,7 @@ class NoOpBuildEnvironment(BuildEnvironment): finder: "PackageFinder", requirements: Iterable[str], prefix_as_string: str, - message: str, + *, + kind: str, ) -> None: raise NotImplementedError() diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index 81c443adf49d700912ccc1ac106f20849e4f9729..f5dc0fecf788a7f71a690ff2a7ed86f755f29113 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/src/pip/_internal/cli/base_command.py @@ -166,7 +166,7 @@ class Command(CommandContextMixIn): assert isinstance(status, int) return status except DiagnosticPipError as exc: - logger.error("[present-diagnostic]", exc) + logger.error("[present-diagnostic] %s", exc) logger.debug("Exception information:", exc_info=True) return ERROR diff --git a/src/pip/_internal/cli/cmdoptions.py b/src/pip/_internal/cli/cmdoptions.py index 11ddc610c14d1f765fb716d80423625d04bf1396..6e43928f6ee13eb6fe286e59b456dd906ed88a2b 100644 --- a/src/pip/_internal/cli/cmdoptions.py +++ b/src/pip/_internal/cli/cmdoptions.py @@ -10,9 +10,9 @@ pass on state. To be consistent, all options will follow this design. # The following comment should be removed at some point in the future. # mypy: strict-optional=False +import logging import os import textwrap -import warnings from functools import partial from optparse import SUPPRESS_HELP, Option, OptionGroup, OptionParser, Values from textwrap import dedent @@ -30,6 +30,8 @@ from pip._internal.models.target_python import TargetPython from pip._internal.utils.hashes import STRONG_HASHES from pip._internal.utils.misc import strtobool +logger = logging.getLogger(__name__) + def raise_option_error(parser: OptionParser, option: Option, msg: str) -> None: """ @@ -76,10 +78,9 @@ def check_install_build_global( if any(map(getname, names)): control = options.format_control control.disallow_binaries() - warnings.warn( + logger.warning( "Disabling all use of wheels due to the use of --build-option " "/ --global-option / --install-option.", - stacklevel=2, ) diff --git a/src/pip/_internal/distributions/sdist.py b/src/pip/_internal/distributions/sdist.py index 1d8e55bd2b481c6c1d2b238d75eb16e2ff9d25df..bdaf4033c9364f3513f0d6bade7892fd6ae35128 100644 --- a/src/pip/_internal/distributions/sdist.py +++ b/src/pip/_internal/distributions/sdist.py @@ -54,7 +54,7 @@ class SourceDistribution(AbstractDistribution): self.req.build_env = BuildEnvironment() self.req.build_env.install_requirements( - finder, pyproject_requires, "overlay", "Installing build dependencies" + finder, pyproject_requires, "overlay", kind="build dependencies" ) conflicting, missing = self.req.build_env.check_requirements( self.req.requirements_to_check @@ -106,7 +106,7 @@ class SourceDistribution(AbstractDistribution): if conflicting: self._raise_conflicts("the backend dependencies", conflicting) self.req.build_env.install_requirements( - finder, missing, "normal", "Installing backend dependencies" + finder, missing, "normal", kind="backend dependencies" ) def _raise_conflicts( diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index 952e063d78994d4916f449e9c177a510a7a8d3b0..97b9612a187a5e97579551e82244bcc30eacb3bf 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -1,4 +1,9 @@ -"""Exceptions used throughout package""" +"""Exceptions used throughout package. + +This module MUST NOT try to import from anything within `pip._internal` to +operate. This is expected to be importable from any/all files within the +subpackage and, thus, should not depend on them. +""" import configparser import re @@ -347,18 +352,78 @@ class MetadataInconsistent(InstallationError): return template.format(self.ireq, self.field, self.f_val, self.m_val) -class InstallationSubprocessError(InstallationError): - """A subprocess call failed during installation.""" +class LegacyInstallFailure(DiagnosticPipError): + """Error occurred while executing `setup.py install`""" + + reference = "legacy-install-failure" - def __init__(self, returncode: int, description: str) -> None: - self.returncode = returncode - self.description = description + def __init__(self, package_details: str) -> None: + super().__init__( + message="Encountered error while trying to install package.", + context=package_details, + hint_stmt="See above for output from the failure.", + note_stmt="This is an issue with the package mentioned above, not pip.", + ) + + +class InstallationSubprocessError(DiagnosticPipError, InstallationError): + """A subprocess call failed.""" + + reference = "subprocess-exited-with-error" + + def __init__( + self, + *, + command_description: str, + exit_code: int, + output_lines: Optional[List[str]], + ) -> None: + if output_lines is None: + output_prompt = Text("See above for output.") + else: + output_prompt = ( + Text.from_markup(f"[red][{len(output_lines)} lines of output][/]\n") + + Text("".join(output_lines)) + + Text.from_markup(R"[red]\[end of output][/]") + ) + + super().__init__( + message=( + f"[green]{escape(command_description)}[/] did not run successfully.\n" + f"exit code: {exit_code}" + ), + context=output_prompt, + hint_stmt=None, + note_stmt=( + "This error originates from a subprocess, and is likely not a " + "problem with pip." + ), + ) + + self.command_description = command_description + self.exit_code = exit_code def __str__(self) -> str: - return ( - "Command errored out with exit status {}: {} " - "Check the logs for full command output." - ).format(self.returncode, self.description) + return f"{self.command_description} exited with {self.exit_code}" + + +class MetadataGenerationFailed(InstallationSubprocessError, InstallationError): + reference = "metadata-generation-failed" + + def __init__( + self, + *, + package_details: str, + ) -> None: + super(InstallationSubprocessError, self).__init__( + message="Encountered error while generating package metadata.", + context=escape(package_details), + hint_stmt="See above for details.", + note_stmt="This is an issue with the package mentioned above, not pip.", + ) + + def __str__(self) -> str: + return "metadata generation failed" class HashErrors(InstallationError): diff --git a/src/pip/_internal/operations/build/metadata.py b/src/pip/_internal/operations/build/metadata.py index 7d12438d6ed08c527a4a9ef06bcce1bf8c2a840c..e2b7b4445437c53790e41af448dc14d86d9aa729 100644 --- a/src/pip/_internal/operations/build/metadata.py +++ b/src/pip/_internal/operations/build/metadata.py @@ -6,11 +6,17 @@ import os from pip._vendor.pep517.wrappers import Pep517HookCaller from pip._internal.build_env import BuildEnvironment +from pip._internal.exceptions import ( + InstallationSubprocessError, + MetadataGenerationFailed, +) from pip._internal.utils.subprocess import runner_with_spinner_message from pip._internal.utils.temp_dir import TempDirectory -def generate_metadata(build_env: BuildEnvironment, backend: Pep517HookCaller) -> str: +def generate_metadata( + build_env: BuildEnvironment, backend: Pep517HookCaller, details: str +) -> str: """Generate metadata using mechanisms described in PEP 517. Returns the generated metadata directory. @@ -25,6 +31,9 @@ def generate_metadata(build_env: BuildEnvironment, backend: Pep517HookCaller) -> # consider the possibility that this hook doesn't exist. runner = runner_with_spinner_message("Preparing metadata (pyproject.toml)") with backend.subprocess_runner(runner): - distinfo_dir = backend.prepare_metadata_for_build_wheel(metadata_dir) + try: + distinfo_dir = backend.prepare_metadata_for_build_wheel(metadata_dir) + except InstallationSubprocessError as error: + raise MetadataGenerationFailed(package_details=details) from error return os.path.join(metadata_dir, distinfo_dir) diff --git a/src/pip/_internal/operations/build/metadata_editable.py b/src/pip/_internal/operations/build/metadata_editable.py index 13de75f6c98bd2e54a320f300a34727f7a1c7146..4c3f48b6cdfb3087a833546410fc810a343b9e13 100644 --- a/src/pip/_internal/operations/build/metadata_editable.py +++ b/src/pip/_internal/operations/build/metadata_editable.py @@ -6,12 +6,16 @@ import os from pip._vendor.pep517.wrappers import Pep517HookCaller from pip._internal.build_env import BuildEnvironment +from pip._internal.exceptions import ( + InstallationSubprocessError, + MetadataGenerationFailed, +) from pip._internal.utils.subprocess import runner_with_spinner_message from pip._internal.utils.temp_dir import TempDirectory def generate_editable_metadata( - build_env: BuildEnvironment, backend: Pep517HookCaller + build_env: BuildEnvironment, backend: Pep517HookCaller, details: str ) -> str: """Generate metadata using mechanisms described in PEP 660. @@ -29,6 +33,9 @@ def generate_editable_metadata( "Preparing editable metadata (pyproject.toml)" ) with backend.subprocess_runner(runner): - distinfo_dir = backend.prepare_metadata_for_build_editable(metadata_dir) + try: + distinfo_dir = backend.prepare_metadata_for_build_editable(metadata_dir) + except InstallationSubprocessError as error: + raise MetadataGenerationFailed(package_details=details) from error return os.path.join(metadata_dir, distinfo_dir) diff --git a/src/pip/_internal/operations/build/metadata_legacy.py b/src/pip/_internal/operations/build/metadata_legacy.py index ff52de9c4cfcb65aa204104b658b86bf142606d3..e60988d643e007801f79e8718354e7d00c7acf18 100644 --- a/src/pip/_internal/operations/build/metadata_legacy.py +++ b/src/pip/_internal/operations/build/metadata_legacy.py @@ -6,7 +6,11 @@ import os from pip._internal.build_env import BuildEnvironment from pip._internal.cli.spinners import open_spinner -from pip._internal.exceptions import InstallationError +from pip._internal.exceptions import ( + InstallationError, + InstallationSubprocessError, + MetadataGenerationFailed, +) from pip._internal.utils.setuptools_build import make_setuptools_egg_info_args from pip._internal.utils.subprocess import call_subprocess from pip._internal.utils.temp_dir import TempDirectory @@ -56,12 +60,15 @@ def generate_metadata( with build_env: with open_spinner("Preparing metadata (setup.py)") as spinner: - call_subprocess( - args, - cwd=source_dir, - command_desc="python setup.py egg_info", - spinner=spinner, - ) + try: + call_subprocess( + args, + cwd=source_dir, + command_desc="python setup.py egg_info", + spinner=spinner, + ) + except InstallationSubprocessError as error: + raise MetadataGenerationFailed(package_details=details) from error # Return the .egg-info directory. return _find_egg_info(egg_info_dir) diff --git a/src/pip/_internal/operations/build/wheel_legacy.py b/src/pip/_internal/operations/build/wheel_legacy.py index 2d5cb264ee6a0cc25e8a893db6fec277fce65c1f..c5f0492ccbe9c727c835c12c84a1d8340366fa1e 100644 --- a/src/pip/_internal/operations/build/wheel_legacy.py +++ b/src/pip/_internal/operations/build/wheel_legacy.py @@ -4,11 +4,7 @@ from typing import List, Optional from pip._internal.cli.spinners import open_spinner from pip._internal.utils.setuptools_build import make_setuptools_bdist_wheel_args -from pip._internal.utils.subprocess import ( - LOG_DIVIDER, - call_subprocess, - format_command_args, -) +from pip._internal.utils.subprocess import call_subprocess, format_command_args logger = logging.getLogger(__name__) @@ -28,7 +24,7 @@ def format_command_result( else: if not command_output.endswith("\n"): command_output += "\n" - text += f"Command output:\n{command_output}{LOG_DIVIDER}" + text += f"Command output:\n{command_output}" return text @@ -86,6 +82,7 @@ def build_wheel_legacy( try: output = call_subprocess( wheel_args, + command_desc="python setup.py bdist_wheel", cwd=source_dir, spinner=spinner, ) diff --git a/src/pip/_internal/operations/install/editable_legacy.py b/src/pip/_internal/operations/install/editable_legacy.py index 5bd72ca198d299f8ba752e326f0c610d37cc4fd0..bb548cdca75a924bf090f2be29779e2be1951a2c 100644 --- a/src/pip/_internal/operations/install/editable_legacy.py +++ b/src/pip/_internal/operations/install/editable_legacy.py @@ -42,5 +42,6 @@ def install_editable( with build_env: call_subprocess( args, + command_desc="python setup.py develop", cwd=unpacked_source_directory, ) diff --git a/src/pip/_internal/operations/install/legacy.py b/src/pip/_internal/operations/install/legacy.py index 2206c9309136bcc4439888a0622820a4a8c9cfa7..5b7ef9017181e94a86b8985f7523feaea387f612 100644 --- a/src/pip/_internal/operations/install/legacy.py +++ b/src/pip/_internal/operations/install/legacy.py @@ -7,9 +7,8 @@ from distutils.util import change_root from typing import List, Optional, Sequence from pip._internal.build_env import BuildEnvironment -from pip._internal.exceptions import InstallationError +from pip._internal.exceptions import InstallationError, LegacyInstallFailure from pip._internal.models.scheme import Scheme -from pip._internal.utils.logging import indent_log from pip._internal.utils.misc import ensure_dir from pip._internal.utils.setuptools_build import make_setuptools_install_args from pip._internal.utils.subprocess import runner_with_spinner_message @@ -18,10 +17,6 @@ from pip._internal.utils.temp_dir import TempDirectory logger = logging.getLogger(__name__) -class LegacyInstallFailure(Exception): - pass - - def write_installed_files_from_setuptools_record( record_lines: List[str], root: Optional[str], @@ -98,7 +93,7 @@ def install( runner = runner_with_spinner_message( f"Running setup.py install for {req_name}" ) - with indent_log(), build_env: + with build_env: runner( cmd=install_args, cwd=unpacked_source_directory, @@ -111,7 +106,7 @@ def install( except Exception as e: # Signal to the caller that we didn't install the new package - raise LegacyInstallFailure from e + raise LegacyInstallFailure(package_details=req_name) from e # At this point, we have successfully installed the requirement. diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index bd8da9ebd05c61490031219becd72eec04911086..02dbda1941f845a8087ea4544271fa94b69a8bda 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -19,7 +19,7 @@ from pip._vendor.packaging.version import parse as parse_version from pip._vendor.pep517.wrappers import Pep517HookCaller from pip._internal.build_env import BuildEnvironment, NoOpBuildEnvironment -from pip._internal.exceptions import InstallationError +from pip._internal.exceptions import InstallationError, LegacyInstallFailure from pip._internal.locations import get_scheme from pip._internal.metadata import ( BaseDistribution, @@ -35,7 +35,6 @@ from pip._internal.operations.build.metadata_legacy import ( from pip._internal.operations.install.editable_legacy import ( install_editable as install_editable_legacy, ) -from pip._internal.operations.install.legacy import LegacyInstallFailure from pip._internal.operations.install.legacy import install as install_legacy from pip._internal.operations.install.wheel import install_wheel from pip._internal.pyproject import load_pyproject_toml, make_pyproject_path @@ -505,6 +504,7 @@ class InstallRequirement: Under legacy processing, call setup.py egg-info. """ assert self.source_dir + details = self.name or f"from {self.link}" if self.use_pep517: assert self.pep517_backend is not None @@ -516,11 +516,13 @@ class InstallRequirement: self.metadata_directory = generate_editable_metadata( build_env=self.build_env, backend=self.pep517_backend, + details=details, ) else: self.metadata_directory = generate_metadata( build_env=self.build_env, backend=self.pep517_backend, + details=details, ) else: self.metadata_directory = generate_metadata_legacy( @@ -528,7 +530,7 @@ class InstallRequirement: setup_py_path=self.setup_py_path, source_dir=self.unpacked_source_directory, isolated=self.isolated, - details=self.name or f"from {self.link}", + details=details, ) # Act on the newly generated metadata, based on the name and version. @@ -806,7 +808,7 @@ class InstallRequirement: ) except LegacyInstallFailure as exc: self.install_succeeded = False - raise exc.__cause__ + raise exc except Exception: self.install_succeeded = True raise diff --git a/src/pip/_internal/resolution/resolvelib/candidates.py b/src/pip/_internal/resolution/resolvelib/candidates.py index c049255fc96cd0b745235625fcfbe1de419821be..9b8450e86b8354c3e3ebac3aa05eada8a9837d81 100644 --- a/src/pip/_internal/resolution/resolvelib/candidates.py +++ b/src/pip/_internal/resolution/resolvelib/candidates.py @@ -5,7 +5,11 @@ from typing import TYPE_CHECKING, Any, FrozenSet, Iterable, Optional, Tuple, Uni from pip._vendor.packaging.utils import NormalizedName, canonicalize_name from pip._vendor.packaging.version import Version -from pip._internal.exceptions import HashError, MetadataInconsistent +from pip._internal.exceptions import ( + HashError, + InstallationSubprocessError, + MetadataInconsistent, +) from pip._internal.metadata import BaseDistribution from pip._internal.models.link import Link, links_equivalent from pip._internal.models.wheel import Wheel @@ -227,6 +231,11 @@ class _InstallRequirementBackedCandidate(Candidate): # offending line to the user. e.req = self._ireq raise + except InstallationSubprocessError as exc: + # The output has been presented already, so don't duplicate it. + exc.context = "See above for output." + raise + self._check_metadata_consistency(dist) return dist diff --git a/src/pip/_internal/resolution/resolvelib/factory.py b/src/pip/_internal/resolution/resolvelib/factory.py index a54dfd3256ae9e0ef540d4f0c22f370b1f20d201..8c28d0014dc4d5b6d4411426716aaf9dad86fd32 100644 --- a/src/pip/_internal/resolution/resolvelib/factory.py +++ b/src/pip/_internal/resolution/resolvelib/factory.py @@ -191,7 +191,12 @@ class Factory: version=version, ) except (InstallationSubprocessError, MetadataInconsistent) as e: - logger.warning("Discarding %s. %s", link, e) + logger.info( + "Discarding [blue underline]%s[/]: [yellow]%s[reset]", + link, + e, + extra={"markup": True}, + ) self._build_failures[link] = e return None base: BaseCandidate = self._editable_candidate_cache[link] @@ -206,7 +211,12 @@ class Factory: version=version, ) except (InstallationSubprocessError, MetadataInconsistent) as e: - logger.warning("Discarding %s. %s", link, e) + logger.info( + "Discarding [blue underline]%s[/]: [yellow]%s[reset]", + link, + e, + extra={"markup": True}, + ) self._build_failures[link] = e return None base = self._link_candidate_cache[link] diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 1c0cd8e261e051ad5e4d59ae86d24c1e18b0c02f..6e001c5d63cfb058bbbc0351f067c036aa36c6cc 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -152,7 +152,7 @@ class RichPipStreamHandler(RichHandler): style: Optional[Style] = None # If we are given a diagnostic error to present, present it with indentation. - if record.msg == "[present-diagnostic]" and len(record.args) == 1: + if record.msg == "[present-diagnostic] %s" and len(record.args) == 1: diagnostic_error: DiagnosticPipError = record.args[0] # type: ignore[index] assert isinstance(diagnostic_error, DiagnosticPipError) diff --git a/src/pip/_internal/utils/setuptools_build.py b/src/pip/_internal/utils/setuptools_build.py index 9d65ceba4ab041d65c07b3501f4eabe2f5654843..f460c4003f32fea2008eaf7ce590e1dd6a4e36e9 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -1,21 +1,49 @@ import sys +import textwrap from typing import List, Optional, Sequence # Shim to wrap setup.py invocation with setuptools -# -# We set sys.argv[0] to the path to the underlying setup.py file so -# setuptools / distutils don't take the path to the setup.py to be "-c" when -# invoking via the shim. This avoids e.g. the following manifest_maker -# warning: "warning: manifest_maker: standard file '-c' not found". -_SETUPTOOLS_SHIM = ( - "import io, os, sys, setuptools, tokenize; sys.argv[0] = {0!r}; __file__={0!r};" - "f = getattr(tokenize, 'open', open)(__file__) " - "if os.path.exists(__file__) " - "else io.StringIO('from setuptools import setup; setup()');" - "code = f.read().replace('\\r\\n', '\\n');" - "f.close();" - "exec(compile(code, __file__, 'exec'))" -) +# Note that __file__ is handled via two {!r} *and* %r, to ensure that paths on +# Windows are correctly handled (it should be "C:\\Users" not "C:\Users"). +_SETUPTOOLS_SHIM = textwrap.dedent( + """ + exec(compile(''' + # This is -- a caller that pip uses to run setup.py + # + # - It imports setuptools before invoking setup.py, to enable projects that directly + # import from `distutils.core` to work with newer packaging standards. + # - It provides a clear error message when setuptools is not installed. + # - It sets `sys.argv[0]` to the underlying `setup.py`, when invoking `setup.py` so + # setuptools doesn't think the script is `-c`. This avoids the following warning: + # manifest_maker: standard file '-c' not found". + # - It generates a shim setup.py, for handling setup.cfg-only projects. + import os, sys, tokenize + + try: + import setuptools + except ImportError as error: + print( + "ERROR: Can not execute `setup.py` since setuptools is not available in " + "the build environment.", + file=sys.stderr, + ) + sys.exit(1) + + __file__ = %r + sys.argv[0] = __file__ + + if os.path.exists(__file__): + filename = __file__ + with tokenize.open(__file__) as f: + setup_py_code = f.read() + else: + filename = "" + setup_py_code = "from setuptools import setup; setup()" + + exec(compile(setup_py_code, filename, "exec")) + ''' % ({!r},), "", "exec")) + """ +).rstrip() def make_setuptools_shim_args( diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index f6e8b219a6ff7941a0ed348e95af7ead9be86c06..b5b762418f503a794f52652780cca5e8052f79bd 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -13,6 +13,8 @@ from typing import ( Union, ) +from pip._vendor.rich.markup import escape + from pip._internal.cli.spinners import SpinnerInterface, open_spinner from pip._internal.exceptions import InstallationSubprocessError from pip._internal.utils.logging import VERBOSE, subprocess_logger @@ -27,9 +29,6 @@ if TYPE_CHECKING: CommandArgs = List[Union[str, HiddenText]] -LOG_DIVIDER = "----------------------------------------" - - def make_command(*args: Union[str, HiddenText, CommandArgs]) -> CommandArgs: """ Create a CommandArgs object. @@ -69,53 +68,19 @@ def reveal_command_args(args: Union[List[str], CommandArgs]) -> List[str]: return [arg.secret if isinstance(arg, HiddenText) else arg for arg in args] -def make_subprocess_output_error( - cmd_args: Union[List[str], CommandArgs], - cwd: Optional[str], - lines: List[str], - exit_status: int, -) -> str: - """ - Create and return the error message to use to log a subprocess error - with command output. - - :param lines: A list of lines, each ending with a newline. - """ - command = format_command_args(cmd_args) - - # We know the joined output value ends in a newline. - output = "".join(lines) - msg = ( - # Use a unicode string to avoid "UnicodeEncodeError: 'ascii' - # codec can't encode character ..." in Python 2 when a format - # argument (e.g. `output`) has a non-ascii character. - "Command errored out with exit status {exit_status}:\n" - " command: {command_display}\n" - " cwd: {cwd_display}\n" - "Complete output ({line_count} lines):\n{output}{divider}" - ).format( - exit_status=exit_status, - command_display=command, - cwd_display=cwd, - line_count=len(lines), - output=output, - divider=LOG_DIVIDER, - ) - return msg - - def call_subprocess( cmd: Union[List[str], CommandArgs], show_stdout: bool = False, cwd: Optional[str] = None, on_returncode: 'Literal["raise", "warn", "ignore"]' = "raise", extra_ok_returncodes: Optional[Iterable[int]] = None, - command_desc: Optional[str] = None, extra_environ: Optional[Mapping[str, Any]] = None, unset_environ: Optional[Iterable[str]] = None, spinner: Optional[SpinnerInterface] = None, log_failed_cmd: Optional[bool] = True, stdout_only: Optional[bool] = False, + *, + command_desc: str, ) -> str: """ Args: @@ -166,9 +131,6 @@ def call_subprocess( # and we have a spinner. use_spinner = not showing_subprocess and spinner is not None - if command_desc is None: - command_desc = format_command_args(cmd) - log_subprocess("Running command %s", command_desc) env = os.environ.copy() if extra_environ: @@ -241,17 +203,25 @@ def call_subprocess( spinner.finish("done") if proc_had_error: if on_returncode == "raise": - if not showing_subprocess and log_failed_cmd: - # Then the subprocess streams haven't been logged to the - # console yet. - msg = make_subprocess_output_error( - cmd_args=cmd, - cwd=cwd, - lines=all_output, - exit_status=proc.returncode, + error = InstallationSubprocessError( + command_description=command_desc, + exit_code=proc.returncode, + output_lines=all_output if not showing_subprocess else None, + ) + if log_failed_cmd: + subprocess_logger.error("[present-diagnostic] %s", error) + subprocess_logger.verbose( + "[bold magenta]full command[/]: [blue]%s[/]", + escape(format_command_args(cmd)), + extra={"markup": True}, + ) + subprocess_logger.verbose( + "[bold magenta]cwd[/]: %s", + escape(cwd or "[inherit]"), + extra={"markup": True}, ) - subprocess_logger.error(msg) - raise InstallationSubprocessError(proc.returncode, command_desc) + + raise error elif on_returncode == "warn": subprocess_logger.warning( 'Command "%s" had error code %s in %s', @@ -281,6 +251,7 @@ def runner_with_spinner_message(message: str) -> Callable[..., None]: with open_spinner(message) as spinner: call_subprocess( cmd, + command_desc=message, cwd=cwd, extra_environ=extra_environ, spinner=spinner, diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index 93be9047269ec9bbed94beddf08b30856eb7a3ec..8d1d499376744954308bdf96f80e5b5a39a24195 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -91,7 +91,12 @@ class Git(VersionControl): return not is_tag_or_branch def get_git_version(self) -> Tuple[int, ...]: - version = self.run_command(["version"], show_stdout=False, stdout_only=True) + version = self.run_command( + ["version"], + command_desc="git version", + show_stdout=False, + stdout_only=True, + ) match = GIT_VERSION_REGEX.match(version) if not match: logger.warning("Can't parse git version: %s", version) diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index 7b93657b9f89909613aea5e38f9585c438dd315b..02bbf68e7ad3ce14f191af24260312e817e12df7 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -31,7 +31,12 @@ from pip._internal.utils.misc import ( is_installable_dir, rmtree, ) -from pip._internal.utils.subprocess import CommandArgs, call_subprocess, make_command +from pip._internal.utils.subprocess import ( + CommandArgs, + call_subprocess, + format_command_args, + make_command, +) from pip._internal.utils.urls import get_url_scheme if TYPE_CHECKING: @@ -639,6 +644,8 @@ class VersionControl: command name, and checks that the VCS is available """ cmd = make_command(cls.name, *cmd) + if command_desc is None: + command_desc = format_command_args(cmd) try: return call_subprocess( cmd, diff --git a/src/pip/_internal/wheel_builder.py b/src/pip/_internal/wheel_builder.py index a9123a0f1f6aa19065cb4184820ed8c219e415b2..d0663443b2207ad8efc0fd56a27d085e821b2eb7 100644 --- a/src/pip/_internal/wheel_builder.py +++ b/src/pip/_internal/wheel_builder.py @@ -310,7 +310,9 @@ def _clean_one_legacy(req: InstallRequirement, global_options: List[str]) -> boo logger.info("Running setup.py clean for %s", req.name) try: - call_subprocess(clean_args, cwd=req.source_dir) + call_subprocess( + clean_args, command_desc="python setup.py clean", cwd=req.source_dir + ) return True except Exception: logger.error("Failed cleaning build dir for %s", req.name) diff --git a/tests/data/src/chattymodule/setup.py b/tests/data/src/chattymodule/setup.py index 507b6466b4de35423fde614f7fa6c4af196cd52c..9f411b6fdff14265de8ee2baf66755be1e96054e 100644 --- a/tests/data/src/chattymodule/setup.py +++ b/tests/data/src/chattymodule/setup.py @@ -6,8 +6,10 @@ import sys from setuptools import setup print(f"HELLO FROM CHATTYMODULE {sys.argv[1]}") -print(os.environ) print(sys.argv) +print(sys.executable) +print(sys.version) + if "--fail" in sys.argv: print("I DIE, I DIE") sys.exit(1) diff --git a/tests/data/src/setup_error/setup.py b/tests/data/src/setup_error/setup.py new file mode 100644 index 0000000000000000000000000000000000000000..d942355ca9377e14b4ef7de2930aa49610e2cfda --- /dev/null +++ b/tests/data/src/setup_error/setup.py @@ -0,0 +1,11 @@ +from setuptools import setup + +# This is to get an error that originates from setuptools, which generates a +# decently sized output. +setup( + cmdclass={ + "egg_info": "", + "install": "", + "bdist_wheel": "", + } +) diff --git a/tests/functional/test_build_env.py b/tests/functional/test_build_env.py index f846b305435b2564c51434b2d1fe9e2a4a4d1787..d114e8d2359f67e839c3310129c26f9ec9eaddd6 100644 --- a/tests/functional/test_build_env.py +++ b/tests/functional/test_build_env.py @@ -81,7 +81,7 @@ def test_build_env_allow_empty_requirements_install() -> None: build_env = BuildEnvironment() for prefix in ("normal", "overlay"): build_env.install_requirements( - finder, [], prefix, "Installing build dependencies" + finder, [], prefix, kind="Installing build dependencies" ) @@ -92,15 +92,15 @@ def test_build_env_allow_only_one_install(script: PipTestEnvironment) -> None: build_env = BuildEnvironment() for prefix in ("normal", "overlay"): build_env.install_requirements( - finder, ["foo"], prefix, f"installing foo in {prefix}" + finder, ["foo"], prefix, kind=f"installing foo in {prefix}" ) with pytest.raises(AssertionError): build_env.install_requirements( - finder, ["bar"], prefix, f"installing bar in {prefix}" + finder, ["bar"], prefix, kind=f"installing bar in {prefix}" ) with pytest.raises(AssertionError): build_env.install_requirements( - finder, [], prefix, f"installing in {prefix}" + finder, [], prefix, kind=f"installing in {prefix}" ) @@ -131,7 +131,7 @@ def test_build_env_requirements_check(script: PipTestEnvironment) -> None: script, """ build_env.install_requirements(finder, ['foo', 'bar==3.0'], 'normal', - 'installing foo in normal') + kind='installing foo in normal') r = build_env.check_requirements(['foo', 'bar', 'other']) assert r == (set(), {'other'}), repr(r) @@ -148,9 +148,9 @@ def test_build_env_requirements_check(script: PipTestEnvironment) -> None: script, """ build_env.install_requirements(finder, ['foo', 'bar==3.0'], 'normal', - 'installing foo in normal') + kind='installing foo in normal') build_env.install_requirements(finder, ['bar==1.0'], 'overlay', - 'installing foo in overlay') + kind='installing foo in overlay') r = build_env.check_requirements(['foo', 'bar', 'other']) assert r == (set(), {'other'}), repr(r) @@ -172,9 +172,9 @@ def test_build_env_overlay_prefix_has_priority(script: PipTestEnvironment) -> No script, """ build_env.install_requirements(finder, ['pkg==2.0'], 'overlay', - 'installing pkg==2.0 in overlay') + kind='installing pkg==2.0 in overlay') build_env.install_requirements(finder, ['pkg==4.3'], 'normal', - 'installing pkg==4.3 in normal') + kind='installing pkg==4.3 in normal') """, """ print(__import__('pkg').__version__) diff --git a/tests/functional/test_install.py b/tests/functional/test_install.py index 6c0ff4d6185eac5a8506465a1efac075c1b13058..ff1b35cb258e3def95a395936c5a73e587c6c27b 100644 --- a/tests/functional/test_install.py +++ b/tests/functional/test_install.py @@ -1739,7 +1739,7 @@ def test_install_editable_with_wrong_egg_name( "fragments." ) in result.stderr if resolver_variant == "2020-resolver": - assert "has inconsistent" in result.stderr, str(result) + assert "has inconsistent" in result.stdout, str(result) else: assert "Successfully installed pkga" in str(result), str(result) diff --git a/tests/functional/test_install_reqs.py b/tests/functional/test_install_reqs.py index 45b1edff9e2fadf3521367e16f47670be5f5a38d..a7f2f46be945edf427586b8c7de44f007967c0bc 100644 --- a/tests/functional/test_install_reqs.py +++ b/tests/functional/test_install_reqs.py @@ -351,6 +351,7 @@ def test_install_option_in_requirements_file_overrides_cli( "-r", str(reqs_file), "--install-option=-O1", + allow_stderr_warning=True, ) simple_args = simple_sdist.args() assert "install" in simple_args @@ -790,6 +791,7 @@ def test_install_options_local_to_package( str(simple1_sdist.sdist_path.parent), "-r", reqs_file, + allow_stderr_warning=True, ) simple1_args = simple1_sdist.args() diff --git a/tests/functional/test_install_vcs_git.py b/tests/functional/test_install_vcs_git.py index 3836a251e2e7ba4aff4ca1ed82d0dd0f6546b372..45db80b6727f3864b31b730044a2ee561e6c8c3a 100644 --- a/tests/functional/test_install_vcs_git.py +++ b/tests/functional/test_install_vcs_git.py @@ -347,6 +347,7 @@ def test_git_with_tag_name_and_update(script: PipTestEnvironment, tmpdir: Path) "--global-option=--version", "-e", new_local_url, + allow_stderr_warning=True, ) assert "0.1.2" in result.stdout @@ -380,7 +381,12 @@ def test_git_with_non_editable_unpacking( rev="0.1.2", egg="pip-test-package", ) - result = script.pip("install", "--global-option=--version", local_url) + result = script.pip( + "install", + "--global-option=--version", + local_url, + allow_stderr_warning=True, + ) assert "0.1.2" in result.stdout diff --git a/tests/functional/test_new_resolver.py b/tests/functional/test_new_resolver.py index da36d41ccc76db37105d102b03e513b745879c1b..b3f523788ea9ff752f229b96948d5d25a7565da7 100644 --- a/tests/functional/test_new_resolver.py +++ b/tests/functional/test_new_resolver.py @@ -1362,7 +1362,7 @@ def test_new_resolver_skip_inconsistent_metadata(script: PipTestEnvironment) -> assert ( " inconsistent version: filename has '3', but metadata has '2'" - ) in result.stderr, str(result) + ) in result.stdout, str(result) script.assert_installed(a="1") diff --git a/tests/functional/test_pep517.py b/tests/functional/test_pep517.py index 6dd8e2be533429edd2f13d4e9bc08dbc4a9d38b4..fb09a2e8ecf90bdeecf24e61b10a8067caa7c2d4 100644 --- a/tests/functional/test_pep517.py +++ b/tests/functional/test_pep517.py @@ -36,7 +36,7 @@ def test_backend(tmpdir: Path, data: TestData) -> None: req.load_pyproject_toml() env = BuildEnvironment() finder = make_test_finder(find_links=[data.backends]) - env.install_requirements(finder, ["dummy_backend"], "normal", "Installing") + env.install_requirements(finder, ["dummy_backend"], "normal", kind="Installing") conflicting, missing = env.check_requirements(["dummy_backend"]) assert not conflicting and not missing assert hasattr(req.pep517_backend, "build_wheel") @@ -83,7 +83,7 @@ def test_backend_path_and_dep(tmpdir: Path, data: TestData) -> None: req.load_pyproject_toml() env = BuildEnvironment() finder = make_test_finder(find_links=[data.backends]) - env.install_requirements(finder, ["dummy_backend"], "normal", "Installing") + env.install_requirements(finder, ["dummy_backend"], "normal", kind="Installing") assert hasattr(req.pep517_backend, "build_wheel") with env: @@ -300,6 +300,7 @@ def test_pep517_and_build_options( "-f", common_wheels, project_dir, + allow_stderr_warning=True, ) assert "Ignoring --build-option when building" in result.stderr assert "using PEP 517" in result.stderr @@ -320,6 +321,7 @@ def test_pep517_and_global_options( "-f", common_wheels, project_dir, + allow_stderr_warning=True, ) assert "Ignoring --global-option when building" in result.stderr assert "using PEP 517" in result.stderr diff --git a/tests/unit/test_utils.py b/tests/unit/test_utils.py index c142c9e9b5ec2c219ca5da8d803472574dbf788e..2d0a82bddf76bef0db5dc246adcb7c3e63e4b1ca 100644 --- a/tests/unit/test_utils.py +++ b/tests/unit/test_utils.py @@ -943,11 +943,14 @@ def test_make_setuptools_shim_args() -> None: ) assert args[1:3] == ["-u", "-c"] - # Spot-check key aspects of the command string. - assert "sys.argv[0] = '/dir/path/setup.py'" in args[3] - assert "__file__='/dir/path/setup.py'" in args[3] assert args[4:] == ["--some", "--option", "--no-user-cfg"] + shim = args[3] + # Spot-check key aspects of the command string. + assert "import setuptools" in shim + assert "'/dir/path/setup.py'" in args[3] + assert "sys.argv[0] = __file__" in args[3] + @pytest.mark.parametrize("global_options", [None, [], ["--some", "--option"]]) def test_make_setuptools_shim_args__global_options( diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index 5d0a9ba8c3b0112dd6498b4934ff1dac111e8c76..c14c407d2df2ca6d9c9d46b89f45a791cff0a6df 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/tests/unit/test_utils_subprocess.py @@ -1,7 +1,6 @@ import locale import sys from logging import DEBUG, ERROR, INFO, WARNING -from textwrap import dedent from typing import List, Optional, Tuple, Type import pytest @@ -15,7 +14,6 @@ from pip._internal.utils.subprocess import ( call_subprocess, format_command_args, make_command, - make_subprocess_output_error, subprocess_logger, ) @@ -40,104 +38,6 @@ def test_format_command_args(args: CommandArgs, expected: str) -> None: assert actual == expected -def test_make_subprocess_output_error() -> None: - cmd_args = ["test", "has space"] - cwd = "/path/to/cwd" - lines = ["line1\n", "line2\n", "line3\n"] - actual = make_subprocess_output_error( - cmd_args=cmd_args, - cwd=cwd, - lines=lines, - exit_status=3, - ) - expected = dedent( - """\ - Command errored out with exit status 3: - command: test 'has space' - cwd: /path/to/cwd - Complete output (3 lines): - line1 - line2 - line3 - ----------------------------------------""" - ) - assert actual == expected, f"actual: {actual}" - - -def test_make_subprocess_output_error__non_ascii_command_arg( - monkeypatch: pytest.MonkeyPatch, -) -> None: - """ - Test a command argument with a non-ascii character. - """ - cmd_args = ["foo", "déf"] - - # We need to monkeypatch so the encoding will be correct on Windows. - monkeypatch.setattr(locale, "getpreferredencoding", lambda: "utf-8") - actual = make_subprocess_output_error( - cmd_args=cmd_args, - cwd="/path/to/cwd", - lines=[], - exit_status=1, - ) - expected = dedent( - """\ - Command errored out with exit status 1: - command: foo 'déf' - cwd: /path/to/cwd - Complete output (0 lines): - ----------------------------------------""" - ) - assert actual == expected, f"actual: {actual}" - - -def test_make_subprocess_output_error__non_ascii_cwd_python_3() -> None: - """ - Test a str (text) cwd with a non-ascii character in Python 3. - """ - cmd_args = ["test"] - cwd = "/path/to/cwd/déf" - actual = make_subprocess_output_error( - cmd_args=cmd_args, - cwd=cwd, - lines=[], - exit_status=1, - ) - expected = dedent( - """\ - Command errored out with exit status 1: - command: test - cwd: /path/to/cwd/déf - Complete output (0 lines): - ----------------------------------------""" - ) - assert actual == expected, f"actual: {actual}" - - -# This test is mainly important for checking unicode in Python 2. -def test_make_subprocess_output_error__non_ascii_line() -> None: - """ - Test a line with a non-ascii character. - """ - lines = ["curly-quote: \u2018\n"] - actual = make_subprocess_output_error( - cmd_args=["test"], - cwd="/path/to/cwd", - lines=lines, - exit_status=1, - ) - expected = dedent( - """\ - Command errored out with exit status 1: - command: test - cwd: /path/to/cwd - Complete output (1 lines): - curly-quote: \u2018 - ----------------------------------------""" - ) - assert actual == expected, f"actual: {actual}" - - @pytest.mark.parametrize( ("stdout_only", "expected"), [ @@ -163,6 +63,7 @@ def test_call_subprocess_stdout_only( "-c", "import sys; sys.stdout.write('out\\n'); sys.stderr.write('err\\n')", ], + command_desc="test stdout_only", stdout_only=stdout_only, ) assert out in expected @@ -271,12 +172,16 @@ class TestCallSubprocess: """ log_level = DEBUG args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner) + result = call_subprocess( + args, + command_desc="test debug logging", + spinner=spinner, + ) expected = ( ["Hello", "world"], [ - ("pip.subprocessor", VERBOSE, "Running command "), + ("pip.subprocessor", VERBOSE, "Running "), ("pip.subprocessor", VERBOSE, "Hello"), ("pip.subprocessor", VERBOSE, "world"), ], @@ -301,7 +206,11 @@ class TestCallSubprocess: """ log_level = INFO args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner) + result = call_subprocess( + args, + command_desc="test info logging", + spinner=spinner, + ) expected: Tuple[List[str], List[Tuple[str, int, str]]] = ( ["Hello", "world"], @@ -331,16 +240,29 @@ class TestCallSubprocess: args, spinner = self.prepare_call(caplog, log_level, command=command) with pytest.raises(InstallationSubprocessError) as exc: - call_subprocess(args, spinner=spinner) + call_subprocess( + args, + command_desc="test info logging with subprocess error", + spinner=spinner, + ) result = None - exc_message = str(exc.value) - assert exc_message.startswith("Command errored out with exit status 1: ") - assert exc_message.endswith("Check the logs for full command output.") + exception = exc.value + assert exception.reference == "subprocess-exited-with-error" + assert "exit code: 1" in exception.message + assert exception.note_stmt + assert "not a problem with pip" in exception.note_stmt + # Check that the process outout is captured, and would be shown. + assert exception.context + assert "Hello\n" in exception.context + assert "fail\n" in exception.context + assert "world\n" in exception.context expected = ( None, [ - ("pip.subprocessor", ERROR, "Complete output (3 lines):\n"), + # pytest's caplog overrides th formatter, which means that we + # won't see the message formatted through our formatters. + ("pip.subprocessor", ERROR, "[present-diagnostic]"), ], ) # The spinner should spin three times in this case since the @@ -355,33 +277,6 @@ class TestCallSubprocess: expected_spinner=(3, "error"), ) - # Do some further checking on the captured log records to confirm - # that the subprocess output was logged. - last_record = caplog.record_tuples[-1] - last_message = last_record[2] - lines = last_message.splitlines() - - # We have to sort before comparing the lines because we can't - # guarantee the order in which stdout and stderr will appear. - # For example, we observed the stderr lines coming before stdout - # in CI for PyPy 2.7 even though stdout happens first chronologically. - actual = sorted(lines) - # Test the "command" line separately because we can't test an - # exact match. - command_line = actual.pop(1) - assert actual == [ - " cwd: None", - "----------------------------------------", - "Command errored out with exit status 1:", - "Complete output (3 lines):", - "Hello", - "fail", - "world", - ], f"lines: {actual}" # Show the full output on failure. - - assert command_line.startswith(" command: ") - assert command_line.endswith('print("world"); exit("fail")\'') - def test_info_logging_with_show_stdout_true( self, capfd: pytest.CaptureFixture[str], caplog: pytest.LogCaptureFixture ) -> None: @@ -390,12 +285,17 @@ class TestCallSubprocess: """ log_level = INFO args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner, show_stdout=True) + result = call_subprocess( + args, + command_desc="test info logging with show_stdout", + spinner=spinner, + show_stdout=True, + ) expected = ( ["Hello", "world"], [ - ("pip.subprocessor", INFO, "Running command "), + ("pip.subprocessor", INFO, "Running "), ("pip.subprocessor", INFO, "Hello"), ("pip.subprocessor", INFO, "world"), ], @@ -456,6 +356,7 @@ class TestCallSubprocess: try: call_subprocess( args, + command_desc="spinner go spinny", show_stdout=show_stdout, extra_ok_returncodes=extra_ok_returncodes, spinner=spinner, @@ -474,6 +375,7 @@ class TestCallSubprocess: call_subprocess( [sys.executable, "-c", "input()"], show_stdout=True, + command_desc="stdin reader", ) @@ -487,9 +389,10 @@ def test_unicode_decode_error(caplog: pytest.LogCaptureFixture) -> None: "-c", "import sys; sys.stdout.buffer.write(b'\\xff')", ], + command_desc="invalid decode output", show_stdout=True, ) assert len(caplog.records) == 2 - # First log record is "Running command ..." + # First log record is "Running ..." assert caplog.record_tuples[1] == ("pip.subprocessor", INFO, "\\xff") diff --git a/tests/unit/test_wheel_builder.py b/tests/unit/test_wheel_builder.py index 9562541ff55d5ce084d73117e656647e7ec9a71b..0468273d66a3930d19d075b4fefa592e13c01440 100644 --- a/tests/unit/test_wheel_builder.py +++ b/tests/unit/test_wheel_builder.py @@ -222,7 +222,6 @@ def test_format_command_result__DEBUG( "Command output:", "output line 1", "output line 2", - "----------------------------------------", ]