diff --git a/news/6651.bugfix b/news/6651.bugfix new file mode 100644 index 00000000000..2a78fac0b34 --- /dev/null +++ b/news/6651.bugfix @@ -0,0 +1 @@ +Improve error message formatting when a command errors out in a subprocess. diff --git a/src/pip/_internal/utils/misc.py b/src/pip/_internal/utils/misc.py index cb470f760a5..91adf17ddb9 100644 --- a/src/pip/_internal/utils/misc.py +++ b/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', diff --git a/tests/functional/test_install.py b/tests/functional/test_install.py index 5550e352251..35939b957e9 100644 --- a/tests/functional/test_install.py +++ b/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 diff --git a/tests/unit/test_utils.py b/tests/unit/test_utils.py index 4a8498bda48..5833ffbfe81 100644 --- a/tests/unit/test_utils.py +++ b/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): """