From 531c991ef9c1cc21417835de55928f8ce1bec6b5 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Fri, 12 Nov 2021 13:38:01 +0000 Subject: [PATCH 01/17] Require every `call_subprocess` call-site to pass `command_desc` This serves as additional context that can be presented in error messages. --- src/pip/_internal/build_env.py | 20 +++++++++---- src/pip/_internal/distributions/sdist.py | 4 +-- .../operations/build/wheel_legacy.py | 1 + .../operations/install/editable_legacy.py | 1 + src/pip/_internal/utils/subprocess.py | 7 ++--- src/pip/_internal/vcs/git.py | 7 ++++- src/pip/_internal/vcs/versioncontrol.py | 9 +++++- src/pip/_internal/wheel_builder.py | 4 ++- tests/functional/test_build_env.py | 18 ++++++------ tests/functional/test_pep517.py | 4 +-- tests/unit/test_utils_subprocess.py | 29 ++++++++++++++++--- 11 files changed, 74 insertions(+), 30 deletions(-) diff --git a/src/pip/_internal/build_env.py b/src/pip/_internal/build_env.py index d326dc8cdb1..daeb7fbc8d7 100644 --- a/src/pip/_internal/build_env.py +++ b/src/pip/_internal/build_env.py @@ -189,7 +189,8 @@ def install_requirements( 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 @@ def install_requirements( finder, requirements, prefix, - message, + kind=kind, ) @staticmethod @@ -212,7 +213,8 @@ def _install_requirements( finder: "PackageFinder", requirements: Iterable[str], prefix: _Prefix, - message: str, + *, + kind: str, ) -> None: args: List[str] = [ sys.executable, @@ -254,8 +256,13 @@ def _install_requirements( 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 @@ def install_requirements( finder: "PackageFinder", requirements: Iterable[str], prefix_as_string: str, - message: str, + *, + kind: str, ) -> None: raise NotImplementedError() diff --git a/src/pip/_internal/distributions/sdist.py b/src/pip/_internal/distributions/sdist.py index 1d8e55bd2b4..bdaf4033c93 100644 --- a/src/pip/_internal/distributions/sdist.py +++ b/src/pip/_internal/distributions/sdist.py @@ -54,7 +54,7 @@ def _prepare_build_backend(self, finder: PackageFinder) -> None: 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 @@ def _install_build_reqs(self, finder: PackageFinder) -> None: 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/operations/build/wheel_legacy.py b/src/pip/_internal/operations/build/wheel_legacy.py index 2d5cb264ee6..2b249ebd471 100644 --- a/src/pip/_internal/operations/build/wheel_legacy.py +++ b/src/pip/_internal/operations/build/wheel_legacy.py @@ -86,6 +86,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 5bd72ca198d..bb548cdca75 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/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index f6e8b219a6f..d351dc14780 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -110,12 +110,13 @@ def call_subprocess( 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 +167,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: @@ -281,6 +279,7 @@ def runner( 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 7a78ad12dd5..1b76ee49000 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -91,7 +91,12 @@ def is_immutable_rev_checkout(self, url: str, dest: str) -> bool: 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 1139051f3e1..d371b25501b 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -31,7 +31,12 @@ 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: @@ -634,6 +639,8 @@ def run_command( 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 a9123a0f1f6..d0663443b22 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/functional/test_build_env.py b/tests/functional/test_build_env.py index f846b305435..d114e8d2359 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_pep517.py b/tests/functional/test_pep517.py index 6dd8e2be533..0b033bff4c1 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: diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index 5d0a9ba8c3b..cde35df4c61 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/tests/unit/test_utils_subprocess.py @@ -163,6 +163,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,7 +272,11 @@ def test_debug_logging( """ 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"], @@ -301,7 +306,11 @@ def test_info_logging( """ 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,7 +340,11 @@ def test_info_logging__subprocess_error( 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: ") @@ -390,7 +403,12 @@ def test_info_logging_with_show_stdout_true( """ 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"], @@ -456,6 +474,7 @@ def test_spinner_finish( try: call_subprocess( args, + command_desc="spinner go spinny", show_stdout=show_stdout, extra_ok_returncodes=extra_ok_returncodes, spinner=spinner, @@ -474,6 +493,7 @@ def test_closes_stdin(self) -> None: call_subprocess( [sys.executable, "-c", "input()"], show_stdout=True, + command_desc="stdin reader", ) @@ -487,6 +507,7 @@ 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, ) From 7a13f7c213b83969abfe62cd45a9dadd9b168cf0 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sun, 14 Nov 2021 08:54:41 +0000 Subject: [PATCH 02/17] Improve our setuptools shim Modernise the shim, to account for the Python 3.2+ support matrix. This also presents clearer error messages on failures, the included comment helps inform users about why this shim exists and the traceback now explicitly mentions `` to make it clearer to users that this shim exists. --- src/pip/_internal/utils/setuptools_build.py | 52 +++++++++++++++------ tests/unit/test_utils.py | 9 ++-- 2 files changed, 44 insertions(+), 17 deletions(-) diff --git a/src/pip/_internal/utils/setuptools_build.py b/src/pip/_internal/utils/setuptools_build.py index 9d65ceba4ab..1b80c13c728 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -1,21 +1,45 @@ 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'))" -) +_SETUPTOOLS_SHIM = textwrap.dedent( + """ + exec(compile(''' + # This is -- a shim 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. + # - Provides a clearer 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: + raise RuntimeError( + "setuptools is not available in the build environment, but is required " + "to use setup.py-based projects with pip." + ) from error + + __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")) + ''', "", "exec")) + """ +).rstrip() def make_setuptools_shim_args( diff --git a/tests/unit/test_utils.py b/tests/unit/test_utils.py index c142c9e9b5e..3d29b3d4201 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 "__file__ = '/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( From 57198c6688530b6f011efc29053d82b2ca4e290d Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Fri, 10 Dec 2021 13:41:05 +0000 Subject: [PATCH 03/17] Use `logger.warning` instead of `warnings.warn` This is more in line with the rest of our output presentation logic. --- src/pip/_internal/cli/cmdoptions.py | 7 ++++--- tests/functional/test_install_reqs.py | 2 ++ tests/functional/test_install_vcs_git.py | 8 +++++++- tests/functional/test_pep517.py | 2 ++ 4 files changed, 15 insertions(+), 4 deletions(-) diff --git a/src/pip/_internal/cli/cmdoptions.py b/src/pip/_internal/cli/cmdoptions.py index 11ddc610c14..6e43928f6ee 100644 --- a/src/pip/_internal/cli/cmdoptions.py +++ b/src/pip/_internal/cli/cmdoptions.py @@ -10,9 +10,9 @@ # 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.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 getname(n: str) -> Optional[Any]: 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/tests/functional/test_install_reqs.py b/tests/functional/test_install_reqs.py index 45b1edff9e2..a7f2f46be94 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 3836a251e2e..45db80b6727 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_pep517.py b/tests/functional/test_pep517.py index 0b033bff4c1..fb09a2e8ecf 100644 --- a/tests/functional/test_pep517.py +++ b/tests/functional/test_pep517.py @@ -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 From 543d0b3165040880550aea92982416b723db85e6 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 14 Dec 2021 19:18:44 +0000 Subject: [PATCH 04/17] Clearly document that exceptions shouldn't import any internals This file should be importable in all other modules, which means it can't be importing any of those modules (to prevent an import loop). --- src/pip/_internal/exceptions.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index 952e063d789..3903b1888b1 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 From 2a617d54551db4951f153a06768dfac15f31832f Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 14 Dec 2021 19:27:28 +0000 Subject: [PATCH 05/17] Improve presentation of `LegacyInstallFailure` These errors now more clearly note where the error occurred and what component is at fault. --- src/pip/_internal/exceptions.py | 14 ++++++++++++++ src/pip/_internal/operations/install/legacy.py | 11 +++-------- src/pip/_internal/req/req_install.py | 3 +-- 3 files changed, 18 insertions(+), 10 deletions(-) diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index 3903b1888b1..a19cff19137 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -352,6 +352,20 @@ def __str__(self) -> str: return template.format(self.ireq, self.field, self.f_val, self.m_val) +class LegacyInstallFailure(DiagnosticPipError): + """Error occurred while executing `setup.py install`""" + + reference = "legacy-install-failure" + + 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(InstallationError): """A subprocess call failed during installation.""" diff --git a/src/pip/_internal/operations/install/legacy.py b/src/pip/_internal/operations/install/legacy.py index 2206c930913..5b7ef901718 100644 --- a/src/pip/_internal/operations/install/legacy.py +++ b/src/pip/_internal/operations/install/legacy.py @@ -7,9 +7,8 @@ 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 @@ 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 6fa6eb2a2a9..e22b33cd2a1 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -19,7 +19,7 @@ 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.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 From 1ee370637f550a17da774e0a275725cb5f4895e1 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 14 Dec 2021 19:33:06 +0000 Subject: [PATCH 06/17] Add diagnostics to `InstallationSubprocessError` This more clearly states where the error came from, presents it in a more approachable format with context provided for what this error is related to. --- src/pip/_internal/exceptions.py | 45 +++++-- .../operations/build/wheel_legacy.py | 8 +- src/pip/_internal/utils/subprocess.py | 68 ++++------- tests/unit/test_utils_subprocess.py | 110 +----------------- 4 files changed, 63 insertions(+), 168 deletions(-) diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index a19cff19137..b8bc1be22b1 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -366,18 +366,45 @@ def __init__(self, package_details: str) -> None: ) -class InstallationSubprocessError(InstallationError): - """A subprocess call failed during installation.""" +class InstallationSubprocessError(DiagnosticPipError, InstallationError): + """A subprocess call failed.""" - def __init__(self, returncode: int, description: str) -> None: - self.returncode = returncode - self.description = description + 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 HashErrors(InstallationError): diff --git a/src/pip/_internal/operations/build/wheel_legacy.py b/src/pip/_internal/operations/build/wheel_legacy.py index 2b249ebd471..c5f0492ccbe 100644 --- a/src/pip/_internal/operations/build/wheel_legacy.py +++ b/src/pip/_internal/operations/build/wheel_legacy.py @@ -4,11 +4,7 @@ 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 diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index d351dc14780..395bbca418f 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -13,6 +13,8 @@ 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 @@ CommandArgs = List[Union[str, HiddenText]] -LOG_DIVIDER = "----------------------------------------" - - def make_command(*args: Union[str, HiddenText, CommandArgs]) -> CommandArgs: """ Create a CommandArgs object. @@ -69,41 +68,6 @@ 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, @@ -239,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]", 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', diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index cde35df4c61..0ff34bca653 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 @@ 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"), [ @@ -169,8 +69,8 @@ def test_call_subprocess_stdout_only( assert out in expected captured = capfd.readouterr() assert captured.err == "" - assert log == ["Running command %s", "out", "err"] or log == [ - "Running command %s", + assert log == ["Running %s", "out", "err"] or log == [ + "Running %s", "err", "out", ] @@ -281,7 +181,7 @@ def test_debug_logging( expected = ( ["Hello", "world"], [ - ("pip.subprocessor", VERBOSE, "Running command "), + ("pip.subprocessor", VERBOSE, "Running "), ("pip.subprocessor", VERBOSE, "Hello"), ("pip.subprocessor", VERBOSE, "world"), ], @@ -413,7 +313,7 @@ def test_info_logging_with_show_stdout_true( expected = ( ["Hello", "world"], [ - ("pip.subprocessor", INFO, "Running command "), + ("pip.subprocessor", INFO, "Running "), ("pip.subprocessor", INFO, "Hello"), ("pip.subprocessor", INFO, "world"), ], @@ -512,5 +412,5 @@ def test_unicode_decode_error(caplog: pytest.LogCaptureFixture) -> None: ) 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") From d527e851461cb6126c1a4dd6b1065e78259d2b0e Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Wed, 15 Dec 2021 12:57:41 +0000 Subject: [PATCH 07/17] Add a dedicated exception for metadata generation failures --- src/pip/_internal/exceptions.py | 19 +++++++++++++++++ .../_internal/operations/build/metadata.py | 13 ++++++++++-- .../operations/build/metadata_editable.py | 11 ++++++++-- .../operations/build/metadata_legacy.py | 21 ++++++++++++------- src/pip/_internal/req/req_install.py | 5 ++++- 5 files changed, 57 insertions(+), 12 deletions(-) diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index b8bc1be22b1..97b9612a187 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -407,6 +407,25 @@ def __str__(self) -> str: 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): """Multiple HashError instances rolled into one for reporting""" diff --git a/src/pip/_internal/operations/build/metadata.py b/src/pip/_internal/operations/build/metadata.py index 7d12438d6ed..72cbe319e03 100644 --- a/src/pip/_internal/operations/build/metadata.py +++ b/src/pip/_internal/operations/build/metadata.py @@ -6,11 +6,17 @@ from pip._vendor.pep517.wrappers import Pep517HookCaller from pip._internal.build_env import BuildEnvironment +from pip._internal.exceptions import ( + MetadataGenerationFailed, + InstallationSubprocessError, +) 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 13de75f6c98..bb79401d15a 100644 --- a/src/pip/_internal/operations/build/metadata_editable.py +++ b/src/pip/_internal/operations/build/metadata_editable.py @@ -6,12 +6,16 @@ from pip._vendor.pep517.wrappers import Pep517HookCaller from pip._internal.build_env import BuildEnvironment +from pip._internal.exceptions import ( + MetadataGenerationFailed, + InstallationSubprocessError, +) 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 ff52de9c4cf..ee5bb9d800e 100644 --- a/src/pip/_internal/operations/build/metadata_legacy.py +++ b/src/pip/_internal/operations/build/metadata_legacy.py @@ -6,7 +6,11 @@ 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, + MetadataGenerationFailed, + InstallationSubprocessError, +) 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/req/req_install.py b/src/pip/_internal/req/req_install.py index e22b33cd2a1..603198c2d7e 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -504,6 +504,7 @@ def prepare_metadata(self) -> None: 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 @@ -515,11 +516,13 @@ def prepare_metadata(self) -> None: 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( @@ -527,7 +530,7 @@ def prepare_metadata(self) -> None: 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. From 68e0bd46c8781f4c82bbc72b799bf0aff2ef0f8e Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Thu, 16 Dec 2021 16:34:11 +0530 Subject: [PATCH 08/17] Add an example setuptools-based package that always fails --- tests/data/src/setup_error/setup.py | 11 +++++++++++ 1 file changed, 11 insertions(+) create mode 100644 tests/data/src/setup_error/setup.py diff --git a/tests/data/src/setup_error/setup.py b/tests/data/src/setup_error/setup.py new file mode 100644 index 00000000000..d942355ca93 --- /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": "", + } +) From 1a0193f9e4cfff88d8e15db828742e3d370230f9 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Thu, 16 Dec 2021 21:00:14 +0530 Subject: [PATCH 09/17] Improve the setuptools caller script --- src/pip/_internal/utils/setuptools_build.py | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/src/pip/_internal/utils/setuptools_build.py b/src/pip/_internal/utils/setuptools_build.py index 1b80c13c728..5ea0b40be11 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -6,11 +6,11 @@ _SETUPTOOLS_SHIM = textwrap.dedent( """ exec(compile(''' - # This is -- a shim that pip uses to run setup.py + # 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. - # - Provides a clearer error message when setuptools is not installed. + # - 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". @@ -20,10 +20,12 @@ try: import setuptools except ImportError as error: - raise RuntimeError( - "setuptools is not available in the build environment, but is required " - "to use setup.py-based projects with pip." - ) from 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__ @@ -37,7 +39,7 @@ setup_py_code = "from setuptools import setup; setup()" exec(compile(setup_py_code, filename, "exec")) - ''', "", "exec")) + ''', "", "exec")) """ ).rstrip() From a835e0a2776ea4986059c505ca82005ebff78f25 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 11 Jan 2022 19:21:49 +0000 Subject: [PATCH 10/17] Prettify messages for discarding candidates due to issues These are more pleasing colours and, more importantly, a clearer presentation style of the package vs the error. --- src/pip/_internal/resolution/resolvelib/factory.py | 14 ++++++++++++-- tests/functional/test_new_resolver.py | 2 +- 2 files changed, 13 insertions(+), 3 deletions(-) diff --git a/src/pip/_internal/resolution/resolvelib/factory.py b/src/pip/_internal/resolution/resolvelib/factory.py index a54dfd3256a..8c28d0014dc 100644 --- a/src/pip/_internal/resolution/resolvelib/factory.py +++ b/src/pip/_internal/resolution/resolvelib/factory.py @@ -191,7 +191,12 @@ def _make_candidate_from_link( 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 @@ def _make_candidate_from_link( 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/tests/functional/test_new_resolver.py b/tests/functional/test_new_resolver.py index da36d41ccc7..b3f523788ea 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") From eb462744da0988058b36a673009a23ae0f5982e2 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 11 Jan 2022 19:22:12 +0000 Subject: [PATCH 11/17] Raise the `LegacyInstallFailure` exception directly --- src/pip/_internal/req/req_install.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index 603198c2d7e..446425b2ff3 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -808,7 +808,7 @@ def install( ) except LegacyInstallFailure as exc: self.install_succeeded = False - raise exc.__cause__ + raise exc except Exception: self.install_succeeded = True raise From deb2d754e713e79096b34c7ca2c75fa5f002ca23 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 11 Jan 2022 19:23:08 +0000 Subject: [PATCH 12/17] Tweak the chattymodule to not leak potentially information I'd like to use this in screenshots, but the os.environ makes it a bit tricky to do. --- tests/data/src/chattymodule/setup.py | 4 +++- tests/functional/test_install.py | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/data/src/chattymodule/setup.py b/tests/data/src/chattymodule/setup.py index 507b6466b4d..9f411b6fdff 100644 --- a/tests/data/src/chattymodule/setup.py +++ b/tests/data/src/chattymodule/setup.py @@ -6,8 +6,10 @@ 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/functional/test_install.py b/tests/functional/test_install.py index 6c0ff4d6185..ff1b35cb258 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) From 40bed179c0770ea876125556fa02933559588c12 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Fri, 14 Jan 2022 11:12:02 +0000 Subject: [PATCH 13/17] Sort imports --- src/pip/_internal/operations/build/metadata.py | 2 +- src/pip/_internal/operations/build/metadata_editable.py | 2 +- src/pip/_internal/operations/build/metadata_legacy.py | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/pip/_internal/operations/build/metadata.py b/src/pip/_internal/operations/build/metadata.py index 72cbe319e03..e2b7b444543 100644 --- a/src/pip/_internal/operations/build/metadata.py +++ b/src/pip/_internal/operations/build/metadata.py @@ -7,8 +7,8 @@ from pip._internal.build_env import BuildEnvironment from pip._internal.exceptions import ( - MetadataGenerationFailed, InstallationSubprocessError, + MetadataGenerationFailed, ) from pip._internal.utils.subprocess import runner_with_spinner_message from pip._internal.utils.temp_dir import TempDirectory diff --git a/src/pip/_internal/operations/build/metadata_editable.py b/src/pip/_internal/operations/build/metadata_editable.py index bb79401d15a..4c3f48b6cdf 100644 --- a/src/pip/_internal/operations/build/metadata_editable.py +++ b/src/pip/_internal/operations/build/metadata_editable.py @@ -7,8 +7,8 @@ from pip._internal.build_env import BuildEnvironment from pip._internal.exceptions import ( - MetadataGenerationFailed, InstallationSubprocessError, + MetadataGenerationFailed, ) from pip._internal.utils.subprocess import runner_with_spinner_message from pip._internal.utils.temp_dir import TempDirectory diff --git a/src/pip/_internal/operations/build/metadata_legacy.py b/src/pip/_internal/operations/build/metadata_legacy.py index ee5bb9d800e..e60988d643e 100644 --- a/src/pip/_internal/operations/build/metadata_legacy.py +++ b/src/pip/_internal/operations/build/metadata_legacy.py @@ -8,8 +8,8 @@ from pip._internal.cli.spinners import open_spinner from pip._internal.exceptions import ( InstallationError, - MetadataGenerationFailed, InstallationSubprocessError, + MetadataGenerationFailed, ) from pip._internal.utils.setuptools_build import make_setuptools_egg_info_args from pip._internal.utils.subprocess import call_subprocess From ba79b1c63941b48180e5324a3120db002c826f6a Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Fri, 14 Jan 2022 14:40:42 +0000 Subject: [PATCH 14/17] :newspaper: --- news/10705.feature.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 news/10705.feature.rst diff --git a/news/10705.feature.rst b/news/10705.feature.rst new file mode 100644 index 00000000000..7ffdeb845ba --- /dev/null +++ b/news/10705.feature.rst @@ -0,0 +1 @@ +Improve presentation of errors from subprocesses. From 94668c6df67e29d6a74b5e7c6772bc789163ec84 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sat, 15 Jan 2022 07:34:53 +0000 Subject: [PATCH 15/17] Pacify unit tests --- src/pip/_internal/cli/base_command.py | 2 +- src/pip/_internal/utils/logging.py | 2 +- src/pip/_internal/utils/subprocess.py | 2 +- tests/unit/test_utils_subprocess.py | 48 +++++++++------------------ tests/unit/test_wheel_builder.py | 1 - 5 files changed, 18 insertions(+), 37 deletions(-) diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index 81c443adf49..f5dc0fecf78 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/src/pip/_internal/cli/base_command.py @@ -166,7 +166,7 @@ def exc_logging_wrapper(*args: Any) -> int: 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/utils/logging.py b/src/pip/_internal/utils/logging.py index 1c0cd8e261e..6e001c5d63c 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -152,7 +152,7 @@ def emit(self, record: logging.LogRecord) -> None: 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/subprocess.py b/src/pip/_internal/utils/subprocess.py index 395bbca418f..b5b762418f5 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -209,7 +209,7 @@ def call_subprocess( output_lines=all_output if not showing_subprocess else None, ) if log_failed_cmd: - subprocess_logger.error("[present-diagnostic]", error) + subprocess_logger.error("[present-diagnostic] %s", error) subprocess_logger.verbose( "[bold magenta]full command[/]: [blue]%s[/]", escape(format_command_args(cmd)), diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index 0ff34bca653..c14c407d2df 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/tests/unit/test_utils_subprocess.py @@ -69,8 +69,8 @@ def test_call_subprocess_stdout_only( assert out in expected captured = capfd.readouterr() assert captured.err == "" - assert log == ["Running %s", "out", "err"] or log == [ - "Running %s", + assert log == ["Running command %s", "out", "err"] or log == [ + "Running command %s", "err", "out", ] @@ -246,14 +246,23 @@ def test_info_logging__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 @@ -268,33 +277,6 @@ def test_info_logging__subprocess_error( 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: diff --git a/tests/unit/test_wheel_builder.py b/tests/unit/test_wheel_builder.py index 9562541ff55..0468273d66a 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", - "----------------------------------------", ] From 2e8e5ad3dfea7eb50bdde002d0e4012eaea19766 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sat, 15 Jan 2022 09:23:51 +0000 Subject: [PATCH 16/17] Don't duplicate output when raising out of distribution preparation --- src/pip/_internal/resolution/resolvelib/candidates.py | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/pip/_internal/resolution/resolvelib/candidates.py b/src/pip/_internal/resolution/resolvelib/candidates.py index c049255fc96..9b8450e86b8 100644 --- a/src/pip/_internal/resolution/resolvelib/candidates.py +++ b/src/pip/_internal/resolution/resolvelib/candidates.py @@ -5,7 +5,11 @@ 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 @@ def _prepare(self) -> BaseDistribution: # 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 From 723b2df7b40b0c9d6c38bac4f20c533ae141b6fc Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 25 Jan 2022 00:44:17 +0000 Subject: [PATCH 17/17] Double-escape paths on Windows This helps ensure that they aren't improperly handled due to the newer string-in-string design for the setuptools invocation script. --- src/pip/_internal/utils/setuptools_build.py | 6 ++++-- tests/unit/test_utils.py | 2 +- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/src/pip/_internal/utils/setuptools_build.py b/src/pip/_internal/utils/setuptools_build.py index 5ea0b40be11..f460c4003f3 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -3,6 +3,8 @@ from typing import List, Optional, Sequence # Shim to wrap setup.py invocation with setuptools +# 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(''' @@ -27,7 +29,7 @@ ) sys.exit(1) - __file__ = {!r} + __file__ = %r sys.argv[0] = __file__ if os.path.exists(__file__): @@ -39,7 +41,7 @@ setup_py_code = "from setuptools import setup; setup()" exec(compile(setup_py_code, filename, "exec")) - ''', "", "exec")) + ''' % ({!r},), "", "exec")) """ ).rstrip() diff --git a/tests/unit/test_utils.py b/tests/unit/test_utils.py index 3d29b3d4201..2d0a82bddf7 100644 --- a/tests/unit/test_utils.py +++ b/tests/unit/test_utils.py @@ -948,7 +948,7 @@ def test_make_setuptools_shim_args() -> None: shim = args[3] # Spot-check key aspects of the command string. assert "import setuptools" in shim - assert "__file__ = '/dir/path/setup.py'" in args[3] + assert "'/dir/path/setup.py'" in args[3] assert "sys.argv[0] = __file__" in args[3]