Merge pull request #6655 from cjerdonek/issue-6651-subprocess-output-…

…formatting

Fix #6651: Improve error message formatting when a command errors out

news/6651.bugfix

@@ -0,0 +1 @@
+Improve error message formatting when a command errors out in a subprocess.

src/pip/_internal/utils/misc.py

@@ -724,6 +724,41 @@ def format_command_args(args):
     return ' '.join(shlex_quote(arg) for arg in args)
 
 
+def make_subprocess_output_error(
+    cmd_args,     # type: List[str]
+    cwd,          # type: Optional[str]
+    lines,        # type: List[Text]
+    exit_status,  # type: int
+):
+    # type: (...) -> Text
+    """
+    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 = (
+        # We need to mark this explicitly as a unicode string to avoid
+        # "UnicodeEncodeError: 'ascii' codec can't encode character ..."
+        # errors in Python 2 since e.g. `output` is a unicode string.
+        u'Command errored out with exit status {exit_status}:\n'
+        ' command: {command}\n'
+        '     cwd: {cwd}\n'
+        'Complete output ({line_count} lines):\n{output}{divider}'
+    ).format(
+        exit_status=exit_status,
+        command=command,
+        cwd=cwd,
+        line_count=len(lines),
+        output=output,
+        divider=LOG_DIVIDER,
+    )
+    return msg
+
+
 def call_subprocess(
     cmd,  # type: List[str]
     show_stdout=False,  # type: bool
@@ -803,6 +838,7 @@ def call_subprocess(
         raise
     all_output = []
     while True:
+        # The "line" value is a unicode string in Python 2.
         line = console_to_str(proc.stdout.readline())
         if not line:
             break
@@ -832,14 +868,18 @@ def call_subprocess(
             if not showing_subprocess:
                 # Then the subprocess streams haven't been logged to the
                 # console yet.
-                subprocess_logger.error(
-                    'Complete output from command %s:', command_desc,
+                msg = make_subprocess_output_error(
+                    cmd_args=cmd,
+                    cwd=cwd,
+                    lines=all_output,
+                    exit_status=proc.returncode,
                 )
-                # The all_output value already ends in a newline.
-                subprocess_logger.error(''.join(all_output) + LOG_DIVIDER)
-            raise InstallationError(
-                'Command "%s" failed with error code %s in %s'
-                % (command_desc, proc.returncode, cwd))
+                subprocess_logger.error(msg)
+            exc_msg = (
+                'Command errored out with exit status {}: {} '
+                'Check the logs for full command output.'
+            ).format(proc.returncode, command_desc)
+            raise InstallationError(exc_msg)
         elif on_returncode == 'warn':
             subprocess_logger.warning(
                 'Command "%s" had error code %s in %s',

tests/functional/test_install.py

@@ -938,7 +938,7 @@ def test_install_package_that_emits_unicode(script, data):
     )
     assert (
         'FakeError: this package designed to fail on install' in result.stderr
-    )
+    ), 'stderr: {}'.format(result.stderr)
     assert 'UnicodeDecodeError' not in result.stderr
     assert 'UnicodeDecodeError' not in result.stdout
 

tests/unit/test_utils.py

@@ -15,6 +15,7 @@
 import warnings
 from io import BytesIO
 from logging import DEBUG, ERROR, INFO, WARNING
+from textwrap import dedent
 
 import pytest
 from mock import Mock, patch
@@ -29,8 +30,8 @@
 from pip._internal.utils.hashes import Hashes, MissingHashes
 from pip._internal.utils.misc import (
     call_subprocess, egg_link_path, ensure_dir, format_command_args,
-    get_installed_distributions, get_prog, normalize_path,
-    normalize_version_info, path_to_url, redact_netloc,
+    get_installed_distributions, get_prog, make_subprocess_output_error,
+    normalize_path, normalize_version_info, path_to_url, redact_netloc,
     redact_password_from_url, remove_auth_from_url, rmtree,
     split_auth_from_netloc, split_auth_netloc_from_url, untar_file, unzip_file,
 )
@@ -744,6 +745,50 @@ def test_format_command_args(args, expected):
     assert actual == expected
 
 
+def test_make_subprocess_output_error():
+    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, 'actual: {}'.format(actual)
+
+
+# This test is mainly important for checking unicode in Python 2.
+def test_make_subprocess_output_error__unicode():
+    """
+    Test a line with non-ascii unicode characters.
+    """
+    lines = [u'curly-quote: \u2018\n']
+    actual = make_subprocess_output_error(
+        cmd_args=['test'],
+        cwd='/path/to/cwd',
+        lines=lines,
+        exit_status=1,
+    )
+    expected = dedent(u"""\
+    Command errored out with exit status 1:
+     command: test
+         cwd: /path/to/cwd
+    Complete output (1 lines):
+    curly-quote: \u2018
+    ----------------------------------------""")
+    assert actual == expected, u'actual: {}'.format(actual)
+
+
 class FakeSpinner(SpinnerInterface):
 
     def __init__(self):
@@ -866,14 +911,17 @@ def test_info_logging__subprocess_error(self, capfd, caplog):
         command = 'print("Hello"); print("world"); exit("fail")'
         args, spinner = self.prepare_call(caplog, log_level, command=command)
 
-        with pytest.raises(InstallationError):
+        with pytest.raises(InstallationError) as exc:
             call_subprocess(args, 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.')
 
         expected = (None, [
-            ('pip.subprocessor', ERROR, 'Complete output from command '),
-            # The "failed" portion is later on in this "Hello" string.
-            ('pip.subprocessor', ERROR, 'Hello'),
+            ('pip.subprocessor', ERROR, 'Complete output (3 lines):\n'),
         ])
         # The spinner should spin three times in this case since the
         # subprocess output isn't being written to the console.
@@ -892,12 +940,22 @@ def test_info_logging__subprocess_error(self, capfd, caplog):
         # 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.
-        assert sorted(lines) == [
+        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',
-        ], 'lines: {}'.format(lines)  # Show the full output on failure.
+        ], 'lines: {}'.format(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, caplog):
         """