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

@@ -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):

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
 

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

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