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 d326dc8cd..daeb7fbc8 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/distributions/sdist.py b/src/pip/_internal/distributions/sdist.py index 1d8e55bd2..bdaf4033c 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/operations/build/wheel_legacy.py b/src/pip/_internal/operations/build/wheel_legacy.py index 2d5cb264e..2b249ebd4 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 5bd72ca19..bb548cdca 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 f6e8b219a..d351dc147 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_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 7a78ad12d..1b76ee490 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 1139051f3..d371b2550 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: @@ -634,6 +639,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 a9123a0f1..d0663443b 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 f846b3054..d114e8d23 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 6dd8e2be5..0b033bff4 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 5d0a9ba8c..cde35df4c 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 @@ 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"], @@ -301,7 +306,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,7 +340,11 @@ 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: ") @@ -390,7 +403,12 @@ 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"], @@ -456,6 +474,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 +493,7 @@ class TestCallSubprocess: 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 9d65ceba4..1b80c13c7 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 c142c9e9b..3d29b3d42 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 11ddc610c..6e43928f6 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/tests/functional/test_install_reqs.py b/tests/functional/test_install_reqs.py index 45b1edff9..a7f2f46be 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 3836a251e..45db80b67 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 0b033bff4..fb09a2e8e 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 952e063d7..3903b1888 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 3903b1888..a19cff191 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -352,6 +352,20 @@ class MetadataInconsistent(InstallationError): 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 2206c9309..5b7ef9017 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 6fa6eb2a2..e22b33cd2 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 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 a19cff191..b8bc1be22 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -366,18 +366,45 @@ class LegacyInstallFailure(DiagnosticPipError): ) -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 2b249ebd4..c5f0492cc 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 diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index d351dc147..395bbca41 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,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.error(msg) - raise InstallationSubprocessError(proc.returncode, command_desc) + subprocess_logger.verbose( + "[bold magenta]cwd[/]: %s", + escape(cwd or "[inherit]"), + extra={"markup": True}, + ) + + 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 cde35df4c..0ff34bca6 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"), [ @@ -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 @@ class TestCallSubprocess: expected = ( ["Hello", "world"], [ - ("pip.subprocessor", VERBOSE, "Running command "), + ("pip.subprocessor", VERBOSE, "Running "), ("pip.subprocessor", VERBOSE, "Hello"), ("pip.subprocessor", VERBOSE, "world"), ], @@ -413,7 +313,7 @@ class TestCallSubprocess: 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 b8bc1be22..97b9612a1 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -407,6 +407,25 @@ class InstallationSubprocessError(DiagnosticPipError, InstallationError): 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 7d12438d6..72cbe319e 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 ( + 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 13de75f6c..bb79401d1 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 ( + 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 ff52de9c4..ee5bb9d80 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, + 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 e22b33cd2..603198c2d 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -504,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 @@ -515,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( @@ -527,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. 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 000000000..d942355ca --- /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 1b80c13c7..5ea0b40be 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -6,11 +6,11 @@ from typing import List, Optional, Sequence _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 @@ _SETUPTOOLS_SHIM = textwrap.dedent( 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 @@ _SETUPTOOLS_SHIM = textwrap.dedent( 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 a54dfd325..8c28d0014 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/tests/functional/test_new_resolver.py b/tests/functional/test_new_resolver.py index da36d41cc..b3f523788 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 603198c2d..446425b2f 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -808,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 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 507b6466b..9f411b6fd 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/functional/test_install.py b/tests/functional/test_install.py index 6c0ff4d61..ff1b35cb2 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 72cbe319e..e2b7b4445 100644 --- a/src/pip/_internal/operations/build/metadata.py +++ b/src/pip/_internal/operations/build/metadata.py @@ -7,8 +7,8 @@ from pip._vendor.pep517.wrappers import Pep517HookCaller 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 bb79401d1..4c3f48b6c 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._vendor.pep517.wrappers import Pep517HookCaller 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 ee5bb9d80..e60988d64 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.build_env import BuildEnvironment 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 000000000..7ffdeb845 --- /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 81c443adf..f5dc0fecf 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/utils/logging.py b/src/pip/_internal/utils/logging.py index 1c0cd8e26..6e001c5d6 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/subprocess.py b/src/pip/_internal/utils/subprocess.py index 395bbca41..b5b762418 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 0ff34bca6..c14c407d2 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 @@ class TestCallSubprocess: 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 @@ 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: diff --git a/tests/unit/test_wheel_builder.py b/tests/unit/test_wheel_builder.py index 9562541ff..0468273d6 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 c049255fc..9b8450e86 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 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 5ea0b40be..f460c4003 100644 --- a/src/pip/_internal/utils/setuptools_build.py +++ b/src/pip/_internal/utils/setuptools_build.py @@ -3,6 +3,8 @@ import textwrap 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 @@ _SETUPTOOLS_SHIM = textwrap.dedent( ) sys.exit(1) - __file__ = {!r} + __file__ = %r sys.argv[0] = __file__ if os.path.exists(__file__): @@ -39,7 +41,7 @@ _SETUPTOOLS_SHIM = textwrap.dedent( 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 3d29b3d42..2d0a82bdd 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]