Improve presentation of errors from subprocesses, during installation

news/10705.feature.rst

@@ -0,0 +1 @@
+Improve presentation of errors from subprocesses.

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()

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

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,
         )
 
 

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(

src/pip/_internal/exceptions.py

@@ -1,4 +1,9 @@
-"""Exceptions used throughout package"""
+"""Exceptions used throughout package.
+
+This module MUST NOT try to import from anything within `pip._internal` to
+operate. This is expected to be importable from any/all files within the
+subpackage and, thus, should not depend on them.
+"""
 
 import configparser
 import re
@@ -347,18 +352,78 @@ def __str__(self) -> str:
         return template.format(self.ireq, self.field, self.f_val, self.m_val)
 
 
-class InstallationSubprocessError(InstallationError):
-    """A subprocess call failed during installation."""
+class LegacyInstallFailure(DiagnosticPipError):
+    """Error occurred while executing `setup.py install`"""
+
+    reference = "legacy-install-failure"
 
-    def __init__(self, returncode: int, description: str) -> None:
-        self.returncode = returncode
-        self.description = description
+    def __init__(self, package_details: str) -> None:
+        super().__init__(
+            message="Encountered error while trying to install package.",
+            context=package_details,
+            hint_stmt="See above for output from the failure.",
+            note_stmt="This is an issue with the package mentioned above, not pip.",
+        )
+
+
+class InstallationSubprocessError(DiagnosticPipError, InstallationError):
+    """A subprocess call failed."""
+
+    reference = "subprocess-exited-with-error"
+
+    def __init__(
+        self,
+        *,
+        command_description: str,
+        exit_code: int,
+        output_lines: Optional[List[str]],
+    ) -> None:
+        if output_lines is None:
+            output_prompt = Text("See above for output.")
+        else:
+            output_prompt = (
+                Text.from_markup(f"[red][{len(output_lines)} lines of output][/]\n")
+                + Text("".join(output_lines))
+                + Text.from_markup(R"[red]\[end of output][/]")
+            )
+
+        super().__init__(
+            message=(
+                f"[green]{escape(command_description)}[/] did not run successfully.\n"
+                f"exit code: {exit_code}"
+            ),
+            context=output_prompt,
+            hint_stmt=None,
+            note_stmt=(
+                "This error originates from a subprocess, and is likely not a "
+                "problem with pip."
+            ),
+        )
+
+        self.command_description = command_description
+        self.exit_code = exit_code
 
     def __str__(self) -> str:
-        return (
-            "Command errored out with exit status {}: {} "
-            "Check the logs for full command output."
-        ).format(self.returncode, self.description)
+        return f"{self.command_description} exited with {self.exit_code}"
+
+
+class MetadataGenerationFailed(InstallationSubprocessError, InstallationError):
+    reference = "metadata-generation-failed"
+
+    def __init__(
+        self,
+        *,
+        package_details: str,
+    ) -> None:
+        super(InstallationSubprocessError, self).__init__(
+            message="Encountered error while generating package metadata.",
+            context=escape(package_details),
+            hint_stmt="See above for details.",
+            note_stmt="This is an issue with the package mentioned above, not pip.",
+        )
+
+    def __str__(self) -> str:
+        return "metadata generation failed"
 
 
 class HashErrors(InstallationError):

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 (
+    InstallationSubprocessError,
+    MetadataGenerationFailed,
+)
 from pip._internal.utils.subprocess import runner_with_spinner_message
 from pip._internal.utils.temp_dir import TempDirectory
 
 
-def generate_metadata(build_env: BuildEnvironment, backend: Pep517HookCaller) -> str:
+def generate_metadata(
+    build_env: BuildEnvironment, backend: Pep517HookCaller, details: str
+) -> str:
     """Generate metadata using mechanisms described in PEP 517.
 
     Returns the generated metadata directory.
@@ -25,6 +31,9 @@ def generate_metadata(build_env: BuildEnvironment, backend: Pep517HookCaller) ->
         # consider the possibility that this hook doesn't exist.
         runner = runner_with_spinner_message("Preparing metadata (pyproject.toml)")
         with backend.subprocess_runner(runner):
-            distinfo_dir = backend.prepare_metadata_for_build_wheel(metadata_dir)
+            try:
+                distinfo_dir = backend.prepare_metadata_for_build_wheel(metadata_dir)
+            except InstallationSubprocessError as error:
+                raise MetadataGenerationFailed(package_details=details) from error
 
     return os.path.join(metadata_dir, distinfo_dir)

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 (
+    InstallationSubprocessError,
+    MetadataGenerationFailed,
+)
 from pip._internal.utils.subprocess import runner_with_spinner_message
 from pip._internal.utils.temp_dir import TempDirectory
 
 
 def generate_editable_metadata(
-    build_env: BuildEnvironment, backend: Pep517HookCaller
+    build_env: BuildEnvironment, backend: Pep517HookCaller, details: str
 ) -> str:
     """Generate metadata using mechanisms described in PEP 660.
 
@@ -29,6 +33,9 @@ def generate_editable_metadata(
             "Preparing editable metadata (pyproject.toml)"
         )
         with backend.subprocess_runner(runner):
-            distinfo_dir = backend.prepare_metadata_for_build_editable(metadata_dir)
+            try:
+                distinfo_dir = backend.prepare_metadata_for_build_editable(metadata_dir)
+            except InstallationSubprocessError as error:
+                raise MetadataGenerationFailed(package_details=details) from error
 
     return os.path.join(metadata_dir, distinfo_dir)

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,
+    InstallationSubprocessError,
+    MetadataGenerationFailed,
+)
 from pip._internal.utils.setuptools_build import make_setuptools_egg_info_args
 from pip._internal.utils.subprocess import call_subprocess
 from pip._internal.utils.temp_dir import TempDirectory
@@ -56,12 +60,15 @@ def generate_metadata(
 
     with build_env:
         with open_spinner("Preparing metadata (setup.py)") as spinner:
-            call_subprocess(
-                args,
-                cwd=source_dir,
-                command_desc="python setup.py egg_info",
-                spinner=spinner,
-            )
+            try:
+                call_subprocess(
+                    args,
+                    cwd=source_dir,
+                    command_desc="python setup.py egg_info",
+                    spinner=spinner,
+                )
+            except InstallationSubprocessError as error:
+                raise MetadataGenerationFailed(package_details=details) from error
 
     # Return the .egg-info directory.
     return _find_egg_info(egg_info_dir)

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
 
@@ -86,6 +82,7 @@ def build_wheel_legacy(
         try:
             output = call_subprocess(
                 wheel_args,
+                command_desc="python setup.py bdist_wheel",
                 cwd=source_dir,
                 spinner=spinner,
             )

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,
             )

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.