From d1bfeec18a2dfda95164d0361726883d63c70210 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Mon, 30 Sep 2019 11:15:06 +0530 Subject: [PATCH 1/8] Move subprocessing related utilities to utils.subprocess --- src/pip/_internal/utils/misc.py | 236 +----------------------- src/pip/_internal/utils/subprocess.py | 247 ++++++++++++++++++++++++++ 2 files changed, 250 insertions(+), 233 deletions(-) create mode 100644 src/pip/_internal/utils/subprocess.py diff --git a/src/pip/_internal/utils/misc.py b/src/pip/_internal/utils/misc.py index 42e913cd893..67729649590 100644 --- a/src/pip/_internal/utils/misc.py +++ b/src/pip/_internal/utils/misc.py @@ -13,7 +13,6 @@ import posixpath import shutil import stat -import subprocess import sys from collections import deque @@ -22,12 +21,12 @@ # why we ignore the type on this import. from pip._vendor.retrying import retry # type: ignore from pip._vendor.six import PY2, text_type -from pip._vendor.six.moves import input, shlex_quote +from pip._vendor.six.moves import input from pip._vendor.six.moves.urllib import parse as urllib_parse from pip._vendor.six.moves.urllib.parse import unquote as urllib_unquote from pip import __version__ -from pip._internal.exceptions import CommandError, InstallationError +from pip._internal.exceptions import CommandError from pip._internal.locations import ( get_major_minor_version, site_packages, @@ -35,7 +34,6 @@ ) from pip._internal.utils.compat import ( WINDOWS, - console_to_str, expanduser, stdlib_pkgs, str_to_display, @@ -54,14 +52,12 @@ if MYPY_CHECK_RUNNING: from typing import ( - Any, AnyStr, Container, Iterable, List, Mapping, Optional, Text, + Any, AnyStr, Container, Iterable, List, Optional, Text, Tuple, Union, cast, ) from pip._vendor.pkg_resources import Distribution - from pip._internal.utils.ui import SpinnerInterface VersionInfo = Tuple[int, int, int] - CommandArgs = List[Union[str, 'HiddenText']] else: # typing's cast() is needed at runtime, but we don't want to import typing. # Thus, we use a dummy no-op version, which we tell mypy to ignore. @@ -74,15 +70,11 @@ def cast(type_, value): # type: ignore 'format_size', 'is_installable_dir', 'normalize_path', 'renames', 'get_prog', - 'call_subprocess', 'captured_stdout', 'ensure_dir', 'get_installed_version', 'remove_auth_from_url'] logger = logging.getLogger(__name__) -subprocess_logger = logging.getLogger('pip.subprocessor') - -LOG_DIVIDER = '----------------------------------------' def get_pip_version(): @@ -533,228 +525,6 @@ def dist_location(dist): return normalize_path(dist.location) -def make_command(*args): - # type: (Union[str, HiddenText, CommandArgs]) -> CommandArgs - """ - Create a CommandArgs object. - """ - command_args = [] # type: CommandArgs - for arg in args: - # Check for list instead of CommandArgs since CommandArgs is - # only known during type-checking. - if isinstance(arg, list): - command_args.extend(arg) - else: - # Otherwise, arg is str or HiddenText. - command_args.append(arg) - - return command_args - - -def format_command_args(args): - # type: (Union[List[str], CommandArgs]) -> str - """ - Format command arguments for display. - """ - # For HiddenText arguments, display the redacted form by calling str(). - # Also, we don't apply str() to arguments that aren't HiddenText since - # this can trigger a UnicodeDecodeError in Python 2 if the argument - # has type unicode and includes a non-ascii character. (The type - # checker doesn't ensure the annotations are correct in all cases.) - return ' '.join( - shlex_quote(str(arg)) if isinstance(arg, HiddenText) - else shlex_quote(arg) for arg in args - ) - - -def reveal_command_args(args): - # type: (Union[List[str], CommandArgs]) -> List[str] - """ - Return the arguments in their raw, unredacted form. - """ - return [ - arg.secret if isinstance(arg, HiddenText) else arg for arg in args - ] - - -def make_subprocess_output_error( - cmd_args, # type: Union[List[str], CommandArgs] - 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) - # Convert `command` and `cwd` to text (unicode in Python 2) so we can use - # them as arguments in the unicode format string below. This avoids - # "UnicodeDecodeError: 'ascii' codec can't decode byte ..." in Python 2 - # if either contains a non-ascii character. - command_display = str_to_display(command, desc='command bytes') - cwd_display = path_to_display(cwd) - - # 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. - u'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_display, - cwd_display=cwd_display, - line_count=len(lines), - output=output, - divider=LOG_DIVIDER, - ) - return msg - - -def call_subprocess( - cmd, # type: Union[List[str], CommandArgs] - show_stdout=False, # type: bool - cwd=None, # type: Optional[str] - on_returncode='raise', # type: str - extra_ok_returncodes=None, # type: Optional[Iterable[int]] - command_desc=None, # type: Optional[str] - extra_environ=None, # type: Optional[Mapping[str, Any]] - unset_environ=None, # type: Optional[Iterable[str]] - spinner=None # type: Optional[SpinnerInterface] -): - # type: (...) -> Text - """ - Args: - show_stdout: if true, use INFO to log the subprocess's stderr and - stdout streams. Otherwise, use DEBUG. Defaults to False. - extra_ok_returncodes: an iterable of integer return codes that are - acceptable, in addition to 0. Defaults to None, which means []. - unset_environ: an iterable of environment variable names to unset - prior to calling subprocess.Popen(). - """ - if extra_ok_returncodes is None: - extra_ok_returncodes = [] - if unset_environ is None: - unset_environ = [] - # Most places in pip use show_stdout=False. What this means is-- - # - # - We connect the child's output (combined stderr and stdout) to a - # single pipe, which we read. - # - We log this output to stderr at DEBUG level as it is received. - # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't - # requested), then we show a spinner so the user can still see the - # subprocess is in progress. - # - If the subprocess exits with an error, we log the output to stderr - # at ERROR level if it hasn't already been displayed to the console - # (e.g. if --verbose logging wasn't enabled). This way we don't log - # the output to the console twice. - # - # If show_stdout=True, then the above is still done, but with DEBUG - # replaced by INFO. - if show_stdout: - # Then log the subprocess output at INFO level. - log_subprocess = subprocess_logger.info - used_level = logging.INFO - else: - # Then log the subprocess output using DEBUG. This also ensures - # it will be logged to the log file (aka user_log), if enabled. - log_subprocess = subprocess_logger.debug - used_level = logging.DEBUG - - # Whether the subprocess will be visible in the console. - showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level - - # Only use the spinner if we're not showing the subprocess output - # 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: - env.update(extra_environ) - for name in unset_environ: - env.pop(name, None) - try: - proc = subprocess.Popen( - # Convert HiddenText objects to the underlying str. - reveal_command_args(cmd), - stderr=subprocess.STDOUT, stdin=subprocess.PIPE, - stdout=subprocess.PIPE, cwd=cwd, env=env, - ) - proc.stdin.close() - except Exception as exc: - subprocess_logger.critical( - "Error %s while executing command %s", exc, command_desc, - ) - 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 - line = line.rstrip() - all_output.append(line + '\n') - - # Show the line immediately. - log_subprocess(line) - # Update the spinner. - if use_spinner: - spinner.spin() - try: - proc.wait() - finally: - if proc.stdout: - proc.stdout.close() - proc_had_error = ( - proc.returncode and proc.returncode not in extra_ok_returncodes - ) - if use_spinner: - if proc_had_error: - spinner.finish("error") - else: - spinner.finish("done") - if proc_had_error: - if on_returncode == 'raise': - if not showing_subprocess: - # 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, - ) - 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', - command_desc, proc.returncode, cwd, - ) - elif on_returncode == 'ignore': - pass - else: - raise ValueError('Invalid value: on_returncode=%s' % - repr(on_returncode)) - return ''.join(all_output) - - def write_output(msg, *args): # type: (str, str) -> None logger.info(msg, *args) diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py new file mode 100644 index 00000000000..135c9b09a5f --- /dev/null +++ b/src/pip/_internal/utils/subprocess.py @@ -0,0 +1,247 @@ +# The following comment should be removed at some point in the future. +# mypy: strict-optional=False + +from __future__ import absolute_import + +import logging +import os +import subprocess + +from pip._vendor.six.moves import shlex_quote + +from pip._internal.exceptions import InstallationError +from pip._internal.utils.compat import console_to_str, str_to_display +from pip._internal.utils.misc import HiddenText, path_to_display +from pip._internal.utils.typing import MYPY_CHECK_RUNNING + +if MYPY_CHECK_RUNNING: + from typing import Any, Iterable, List, Mapping, Optional, Text, Union + from pip._internal.utils.ui import SpinnerInterface + + CommandArgs = List[Union[str, HiddenText]] + + +subprocess_logger = logging.getLogger('pip.subprocessor') +LOG_DIVIDER = '----------------------------------------' + + +def make_command(*args): + # type: (Union[str, HiddenText, CommandArgs]) -> CommandArgs + """ + Create a CommandArgs object. + """ + command_args = [] # type: CommandArgs + for arg in args: + # Check for list instead of CommandArgs since CommandArgs is + # only known during type-checking. + if isinstance(arg, list): + command_args.extend(arg) + else: + # Otherwise, arg is str or HiddenText. + command_args.append(arg) + + return command_args + + +def format_command_args(args): + # type: (Union[List[str], CommandArgs]) -> str + """ + Format command arguments for display. + """ + # For HiddenText arguments, display the redacted form by calling str(). + # Also, we don't apply str() to arguments that aren't HiddenText since + # this can trigger a UnicodeDecodeError in Python 2 if the argument + # has type unicode and includes a non-ascii character. (The type + # checker doesn't ensure the annotations are correct in all cases.) + return ' '.join( + shlex_quote(str(arg)) if isinstance(arg, HiddenText) + else shlex_quote(arg) for arg in args + ) + + +def reveal_command_args(args): + # type: (Union[List[str], CommandArgs]) -> List[str] + """ + Return the arguments in their raw, unredacted form. + """ + return [ + arg.secret if isinstance(arg, HiddenText) else arg for arg in args + ] + + +def make_subprocess_output_error( + cmd_args, # type: Union[List[str], CommandArgs] + 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) + # Convert `command` and `cwd` to text (unicode in Python 2) so we can use + # them as arguments in the unicode format string below. This avoids + # "UnicodeDecodeError: 'ascii' codec can't decode byte ..." in Python 2 + # if either contains a non-ascii character. + command_display = str_to_display(command, desc='command bytes') + cwd_display = path_to_display(cwd) + + # 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. + u'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_display, + cwd_display=cwd_display, + line_count=len(lines), + output=output, + divider=LOG_DIVIDER, + ) + return msg + + +def call_subprocess( + cmd, # type: Union[List[str], CommandArgs] + show_stdout=False, # type: bool + cwd=None, # type: Optional[str] + on_returncode='raise', # type: str + extra_ok_returncodes=None, # type: Optional[Iterable[int]] + command_desc=None, # type: Optional[str] + extra_environ=None, # type: Optional[Mapping[str, Any]] + unset_environ=None, # type: Optional[Iterable[str]] + spinner=None # type: Optional[SpinnerInterface] +): + # type: (...) -> Text + """ + Args: + show_stdout: if true, use INFO to log the subprocess's stderr and + stdout streams. Otherwise, use DEBUG. Defaults to False. + extra_ok_returncodes: an iterable of integer return codes that are + acceptable, in addition to 0. Defaults to None, which means []. + unset_environ: an iterable of environment variable names to unset + prior to calling subprocess.Popen(). + """ + if extra_ok_returncodes is None: + extra_ok_returncodes = [] + if unset_environ is None: + unset_environ = [] + # Most places in pip use show_stdout=False. What this means is-- + # + # - We connect the child's output (combined stderr and stdout) to a + # single pipe, which we read. + # - We log this output to stderr at DEBUG level as it is received. + # - If DEBUG logging isn't enabled (e.g. if --verbose logging wasn't + # requested), then we show a spinner so the user can still see the + # subprocess is in progress. + # - If the subprocess exits with an error, we log the output to stderr + # at ERROR level if it hasn't already been displayed to the console + # (e.g. if --verbose logging wasn't enabled). This way we don't log + # the output to the console twice. + # + # If show_stdout=True, then the above is still done, but with DEBUG + # replaced by INFO. + if show_stdout: + # Then log the subprocess output at INFO level. + log_subprocess = subprocess_logger.info + used_level = logging.INFO + else: + # Then log the subprocess output using DEBUG. This also ensures + # it will be logged to the log file (aka user_log), if enabled. + log_subprocess = subprocess_logger.debug + used_level = logging.DEBUG + + # Whether the subprocess will be visible in the console. + showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level + + # Only use the spinner if we're not showing the subprocess output + # 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: + env.update(extra_environ) + for name in unset_environ: + env.pop(name, None) + try: + proc = subprocess.Popen( + # Convert HiddenText objects to the underlying str. + reveal_command_args(cmd), + stderr=subprocess.STDOUT, stdin=subprocess.PIPE, + stdout=subprocess.PIPE, cwd=cwd, env=env, + ) + proc.stdin.close() + except Exception as exc: + subprocess_logger.critical( + "Error %s while executing command %s", exc, command_desc, + ) + 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 + line = line.rstrip() + all_output.append(line + '\n') + + # Show the line immediately. + log_subprocess(line) + # Update the spinner. + if use_spinner: + spinner.spin() + try: + proc.wait() + finally: + if proc.stdout: + proc.stdout.close() + proc_had_error = ( + proc.returncode and proc.returncode not in extra_ok_returncodes + ) + if use_spinner: + if proc_had_error: + spinner.finish("error") + else: + spinner.finish("done") + if proc_had_error: + if on_returncode == 'raise': + if not showing_subprocess: + # 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, + ) + 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', + command_desc, proc.returncode, cwd, + ) + elif on_returncode == 'ignore': + pass + else: + raise ValueError('Invalid value: on_returncode=%s' % + repr(on_returncode)) + return ''.join(all_output) From 2eafb0218b4d1f10975bd49bbfe0f8533c82eadd Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Mon, 30 Sep 2019 11:15:24 +0530 Subject: [PATCH 2/8] Update all the imports as needed --- src/pip/_internal/build_env.py | 2 +- src/pip/_internal/operations/generate_metadata.py | 3 ++- src/pip/_internal/req/req_install.py | 2 +- src/pip/_internal/utils/logging.py | 3 ++- src/pip/_internal/vcs/bazaar.py | 3 ++- src/pip/_internal/vcs/git.py | 3 ++- src/pip/_internal/vcs/mercurial.py | 3 ++- src/pip/_internal/vcs/subversion.py | 5 +++-- src/pip/_internal/vcs/versioncontrol.py | 6 +++--- src/pip/_internal/wheel.py | 8 +++----- 10 files changed, 21 insertions(+), 17 deletions(-) diff --git a/src/pip/_internal/build_env.py b/src/pip/_internal/build_env.py index e91f71af755..5e6dc4602e0 100644 --- a/src/pip/_internal/build_env.py +++ b/src/pip/_internal/build_env.py @@ -16,7 +16,7 @@ from pip._vendor.pkg_resources import Requirement, VersionConflict, WorkingSet from pip import __file__ as pip_location -from pip._internal.utils.misc import call_subprocess +from pip._internal.utils.subprocess import call_subprocess from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.ui import open_spinner diff --git a/src/pip/_internal/operations/generate_metadata.py b/src/pip/_internal/operations/generate_metadata.py index 9101bd77da8..4d06ca7afed 100644 --- a/src/pip/_internal/operations/generate_metadata.py +++ b/src/pip/_internal/operations/generate_metadata.py @@ -4,8 +4,9 @@ import logging import os -from pip._internal.utils.misc import call_subprocess, ensure_dir +from pip._internal.utils.misc import ensure_dir from pip._internal.utils.setuptools_build import make_setuptools_shim_args +from pip._internal.utils.subprocess import call_subprocess from pip._internal.utils.typing import MYPY_CHECK_RUNNING if MYPY_CHECK_RUNNING: diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index 612e41f7416..c578bf22593 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -38,7 +38,6 @@ _make_build_dir, ask_path_exists, backup_dir, - call_subprocess, display_path, dist_in_site_packages, dist_in_usersite, @@ -50,6 +49,7 @@ ) from pip._internal.utils.packaging import get_metadata from pip._internal.utils.setuptools_build import make_setuptools_shim_args +from pip._internal.utils.subprocess import call_subprocess from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.ui import open_spinner diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index dd5ff9cd080..03725b0c1dd 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -15,7 +15,8 @@ from pip._internal.utils.compat import WINDOWS from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX -from pip._internal.utils.misc import ensure_dir, subprocess_logger +from pip._internal.utils.misc import ensure_dir +from pip._internal.utils.subprocess import subprocess_logger try: import threading diff --git a/src/pip/_internal/vcs/bazaar.py b/src/pip/_internal/vcs/bazaar.py index dc532294948..347c06f9dc7 100644 --- a/src/pip/_internal/vcs/bazaar.py +++ b/src/pip/_internal/vcs/bazaar.py @@ -8,7 +8,8 @@ from pip._vendor.six.moves.urllib import parse as urllib_parse -from pip._internal.utils.misc import display_path, make_command, rmtree +from pip._internal.utils.misc import display_path, rmtree +from pip._internal.utils.subprocess import make_command from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.urls import path_to_url from pip._internal.vcs.versioncontrol import VersionControl, vcs diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index c571405d471..9c2e87ea14f 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -13,7 +13,8 @@ from pip._internal.exceptions import BadCommand from pip._internal.utils.compat import samefile -from pip._internal.utils.misc import display_path, make_command +from pip._internal.utils.misc import display_path +from pip._internal.utils.subprocess import make_command from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.vcs.versioncontrol import ( diff --git a/src/pip/_internal/vcs/mercurial.py b/src/pip/_internal/vcs/mercurial.py index 96298e2a0f3..7679b8640ca 100644 --- a/src/pip/_internal/vcs/mercurial.py +++ b/src/pip/_internal/vcs/mercurial.py @@ -8,7 +8,8 @@ from pip._vendor.six.moves import configparser -from pip._internal.utils.misc import display_path, make_command +from pip._internal.utils.misc import display_path +from pip._internal.utils.subprocess import make_command from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.urls import path_to_url diff --git a/src/pip/_internal/vcs/subversion.py b/src/pip/_internal/vcs/subversion.py index 7f6fca3ee8c..7a2cd9f6def 100644 --- a/src/pip/_internal/vcs/subversion.py +++ b/src/pip/_internal/vcs/subversion.py @@ -11,10 +11,10 @@ from pip._internal.utils.logging import indent_log from pip._internal.utils.misc import ( display_path, - make_command, rmtree, split_auth_from_netloc, ) +from pip._internal.utils.subprocess import make_command from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.vcs.versioncontrol import VersionControl, vcs @@ -26,7 +26,8 @@ if MYPY_CHECK_RUNNING: from typing import Optional, Tuple - from pip._internal.utils.misc import CommandArgs, HiddenText + from pip._internal.utils.subprocess import CommandArgs + from pip._internal.utils.misc import HiddenText from pip._internal.vcs.versioncontrol import AuthInfo, RevOptions diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index d405d27da6f..086b2ba850c 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -18,13 +18,12 @@ from pip._internal.utils.misc import ( ask_path_exists, backup_dir, - call_subprocess, display_path, hide_url, hide_value, - make_command, rmtree, ) +from pip._internal.utils.subprocess import call_subprocess, make_command from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.urls import get_url_scheme @@ -33,7 +32,8 @@ Any, Dict, Iterable, List, Mapping, Optional, Text, Tuple, Type, Union ) from pip._internal.utils.ui import SpinnerInterface - from pip._internal.utils.misc import CommandArgs, HiddenText + from pip._internal.utils.misc import HiddenText + from pip._internal.utils.subprocess import CommandArgs AuthInfo = Tuple[Optional[str], Optional[str]] diff --git a/src/pip/_internal/wheel.py b/src/pip/_internal/wheel.py index 3d3af86a500..7d6a4773dbf 100644 --- a/src/pip/_internal/wheel.py +++ b/src/pip/_internal/wheel.py @@ -38,15 +38,13 @@ from pip._internal.models.link import Link from pip._internal.utils.logging import indent_log from pip._internal.utils.marker_files import has_delete_marker_file -from pip._internal.utils.misc import ( +from pip._internal.utils.misc import captured_stdout, ensure_dir, read_chunks +from pip._internal.utils.setuptools_build import make_setuptools_shim_args +from pip._internal.utils.subprocess import ( LOG_DIVIDER, call_subprocess, - captured_stdout, - ensure_dir, format_command_args, - read_chunks, ) -from pip._internal.utils.setuptools_build import make_setuptools_shim_args from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.ui import open_spinner From e9d79db6c4f538814f741451d10d9378b6547908 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Mon, 30 Sep 2019 11:33:19 +0530 Subject: [PATCH 3/8] Move tests for utils.subprocess to dedicated file --- tests/unit/test_utils.py | 394 --------------------------- tests/unit/test_utils_subprocess.py | 403 ++++++++++++++++++++++++++++ 2 files changed, 403 insertions(+), 394 deletions(-) create mode 100644 tests/unit/test_utils_subprocess.py diff --git a/tests/unit/test_utils.py b/tests/unit/test_utils.py index 8a7933eb4b7..a383f153141 100644 --- a/tests/unit/test_utils.py +++ b/tests/unit/test_utils.py @@ -5,7 +5,6 @@ """ import codecs -import locale import os import shutil import stat @@ -13,8 +12,6 @@ import time import warnings from io import BytesIO -from logging import DEBUG, ERROR, INFO, WARNING -from textwrap import dedent import pytest from mock import Mock, patch @@ -37,15 +34,11 @@ HiddenText, build_netloc, build_url_from_netloc, - call_subprocess, egg_link_path, - format_command_args, get_installed_distributions, get_prog, hide_url, hide_value, - make_command, - make_subprocess_output_error, normalize_path, normalize_version_info, parse_netloc, @@ -59,7 +52,6 @@ split_auth_netloc_from_url, ) from pip._internal.utils.setuptools_build import make_setuptools_shim_args -from pip._internal.utils.ui import SpinnerInterface class Tests_EgglinkPath: @@ -634,392 +626,6 @@ def test_get_prog(self, monkeypatch, argv, executable, expected): assert get_prog() == expected -@pytest.mark.parametrize('args, expected', [ - (['pip', 'list'], 'pip list'), - (['foo', 'space space', 'new\nline', 'double"quote', "single'quote"], - """foo 'space space' 'new\nline' 'double"quote' 'single'"'"'quote'"""), - # Test HiddenText arguments. - (make_command(hide_value('secret1'), 'foo', hide_value('secret2')), - "'****' foo '****'"), -]) -def test_format_command_args(args, expected): - actual = format_command_args(args) - 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) - - -def test_make_subprocess_output_error__non_ascii_command_arg(monkeypatch): - """ - Test a command argument with a non-ascii character. - """ - cmd_args = ['foo', 'déf'] - if sys.version_info[0] == 2: - # Check in Python 2 that the str (bytes object) with the non-ascii - # character has the encoding we expect. (This comes from the source - # code encoding at the top of the file.) - assert cmd_args[1].decode('utf-8') == u'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(u"""\ - Command errored out with exit status 1: - command: foo 'déf' - cwd: /path/to/cwd - Complete output (0 lines): - ----------------------------------------""") - assert actual == expected, u'actual: {}'.format(actual) - - -@pytest.mark.skipif("sys.version_info < (3,)") -def test_make_subprocess_output_error__non_ascii_cwd_python_3(monkeypatch): - """ - 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, 'actual: {}'.format(actual) - - -@pytest.mark.parametrize('encoding', [ - 'utf-8', - # Test a Windows encoding. - 'cp1252', -]) -@pytest.mark.skipif("sys.version_info >= (3,)") -def test_make_subprocess_output_error__non_ascii_cwd_python_2( - monkeypatch, encoding, -): - """ - Test a str (bytes object) cwd with a non-ascii character in Python 2. - """ - cmd_args = ['test'] - cwd = u'/path/to/cwd/déf'.encode(encoding) - monkeypatch.setattr(sys, 'getfilesystemencoding', lambda: encoding) - actual = make_subprocess_output_error( - cmd_args=cmd_args, - cwd=cwd, - lines=[], - exit_status=1, - ) - expected = dedent(u"""\ - Command errored out with exit status 1: - command: test - cwd: /path/to/cwd/déf - Complete output (0 lines): - ----------------------------------------""") - assert actual == expected, u'actual: {}'.format(actual) - - -# This test is mainly important for checking unicode in Python 2. -def test_make_subprocess_output_error__non_ascii_line(): - """ - Test a line with a non-ascii character. - """ - 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): - self.spin_count = 0 - self.final_status = None - - def spin(self): - self.spin_count += 1 - - def finish(self, final_status): - self.final_status = final_status - - -class TestCallSubprocess(object): - - """ - Test call_subprocess(). - """ - - def check_result( - self, capfd, caplog, log_level, spinner, result, expected, - expected_spinner, - ): - """ - Check the result of calling call_subprocess(). - - :param log_level: the logging level that caplog was set to. - :param spinner: the FakeSpinner object passed to call_subprocess() - to be checked. - :param result: the call_subprocess() return value to be checked. - :param expected: a pair (expected_proc, expected_records), where - 1) `expected_proc` is the expected return value of - call_subprocess() as a list of lines, or None if the return - value is expected to be None; - 2) `expected_records` is the expected value of - caplog.record_tuples. - :param expected_spinner: a 2-tuple of the spinner's expected - (spin_count, final_status). - """ - expected_proc, expected_records = expected - - if expected_proc is None: - assert result is None - else: - assert result.splitlines() == expected_proc - - # Confirm that stdout and stderr haven't been written to. - captured = capfd.readouterr() - assert (captured.out, captured.err) == ('', '') - - records = caplog.record_tuples - if len(records) != len(expected_records): - raise RuntimeError('{} != {}'.format(records, expected_records)) - - for record, expected_record in zip(records, expected_records): - # Check the logger_name and log level parts exactly. - assert record[:2] == expected_record[:2] - # For the message portion, check only a substring. Also, we - # can't use startswith() since the order of stdout and stderr - # isn't guaranteed in cases where stderr is also present. - # For example, we observed the stderr lines coming before stdout - # in CI for PyPy 2.7 even though stdout happens first - # chronologically. - assert expected_record[2] in record[2] - - assert (spinner.spin_count, spinner.final_status) == expected_spinner - - def prepare_call(self, caplog, log_level, command=None): - if command is None: - command = 'print("Hello"); print("world")' - - caplog.set_level(log_level) - spinner = FakeSpinner() - args = [sys.executable, '-c', command] - - return (args, spinner) - - def test_debug_logging(self, capfd, caplog): - """ - Test DEBUG logging (and without passing show_stdout=True). - """ - log_level = DEBUG - args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner) - - expected = (['Hello', 'world'], [ - ('pip.subprocessor', DEBUG, 'Running command '), - ('pip.subprocessor', DEBUG, 'Hello'), - ('pip.subprocessor', DEBUG, 'world'), - ]) - # The spinner shouldn't spin in this case since the subprocess - # output is already being logged to the console. - self.check_result( - capfd, caplog, log_level, spinner, result, expected, - expected_spinner=(0, None), - ) - - def test_info_logging(self, capfd, caplog): - """ - Test INFO logging (and without passing show_stdout=True). - """ - log_level = INFO - args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner) - - expected = (['Hello', 'world'], []) - # The spinner should spin twice in this case since the subprocess - # output isn't being written to the console. - self.check_result( - capfd, caplog, log_level, spinner, result, expected, - expected_spinner=(2, 'done'), - ) - - def test_info_logging__subprocess_error(self, capfd, caplog): - """ - Test INFO logging of a subprocess with an error (and without passing - show_stdout=True). - """ - log_level = INFO - command = 'print("Hello"); print("world"); exit("fail")' - args, spinner = self.prepare_call(caplog, log_level, command=command) - - 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 (3 lines):\n'), - ]) - # The spinner should spin three times in this case since the - # subprocess output isn't being written to the console. - self.check_result( - capfd, caplog, log_level, spinner, result, expected, - 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', - ], '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): - """ - Test INFO logging with show_stdout=True. - """ - log_level = INFO - args, spinner = self.prepare_call(caplog, log_level) - result = call_subprocess(args, spinner=spinner, show_stdout=True) - - expected = (['Hello', 'world'], [ - ('pip.subprocessor', INFO, 'Running command '), - ('pip.subprocessor', INFO, 'Hello'), - ('pip.subprocessor', INFO, 'world'), - ]) - # The spinner shouldn't spin in this case since the subprocess - # output is already being written to the console. - self.check_result( - capfd, caplog, log_level, spinner, result, expected, - expected_spinner=(0, None), - ) - - @pytest.mark.parametrize(( - 'exit_status', 'show_stdout', 'extra_ok_returncodes', 'log_level', - 'expected'), - [ - # The spinner should show here because show_stdout=False means - # the subprocess should get logged at DEBUG level, but the passed - # log level is only INFO. - (0, False, None, INFO, (None, 'done', 2)), - # Test some cases where the spinner should not be shown. - (0, False, None, DEBUG, (None, None, 0)), - # Test show_stdout=True. - (0, True, None, DEBUG, (None, None, 0)), - (0, True, None, INFO, (None, None, 0)), - # The spinner should show here because show_stdout=True means - # the subprocess should get logged at INFO level, but the passed - # log level is only WARNING. - (0, True, None, WARNING, (None, 'done', 2)), - # Test a non-zero exit status. - (3, False, None, INFO, (InstallationError, 'error', 2)), - # Test a non-zero exit status also in extra_ok_returncodes. - (3, False, (3, ), INFO, (None, 'done', 2)), - ]) - def test_spinner_finish( - self, exit_status, show_stdout, extra_ok_returncodes, log_level, - caplog, expected, - ): - """ - Test that the spinner finishes correctly. - """ - expected_exc_type = expected[0] - expected_final_status = expected[1] - expected_spin_count = expected[2] - - command = ( - 'print("Hello"); print("world"); exit({})'.format(exit_status) - ) - args, spinner = self.prepare_call(caplog, log_level, command=command) - try: - call_subprocess( - args, - show_stdout=show_stdout, - extra_ok_returncodes=extra_ok_returncodes, - spinner=spinner, - ) - except Exception as exc: - exc_type = type(exc) - else: - exc_type = None - - assert exc_type == expected_exc_type - assert spinner.final_status == expected_final_status - assert spinner.spin_count == expected_spin_count - - def test_closes_stdin(self): - with pytest.raises(InstallationError): - call_subprocess( - [sys.executable, '-c', 'input()'], - show_stdout=True, - ) - - @pytest.mark.parametrize('host_port, expected_netloc', [ # Test domain name. (('example.com', None), 'example.com'), diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py new file mode 100644 index 00000000000..44b8a7b3c45 --- /dev/null +++ b/tests/unit/test_utils_subprocess.py @@ -0,0 +1,403 @@ +# -*- coding: utf-8 -*- +import locale +import sys +from logging import DEBUG, ERROR, INFO, WARNING +from textwrap import dedent + +import pytest + +from pip._internal.exceptions import InstallationError +from pip._internal.utils.misc import hide_value +from pip._internal.utils.subprocess import ( + call_subprocess, + format_command_args, + make_command, + make_subprocess_output_error, +) +from pip._internal.utils.ui import SpinnerInterface + + +@pytest.mark.parametrize('args, expected', [ + (['pip', 'list'], 'pip list'), + (['foo', 'space space', 'new\nline', 'double"quote', "single'quote"], + """foo 'space space' 'new\nline' 'double"quote' 'single'"'"'quote'"""), + # Test HiddenText arguments. + (make_command(hide_value('secret1'), 'foo', hide_value('secret2')), + "'****' foo '****'"), +]) +def test_format_command_args(args, expected): + actual = format_command_args(args) + 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) + + +def test_make_subprocess_output_error__non_ascii_command_arg(monkeypatch): + """ + Test a command argument with a non-ascii character. + """ + cmd_args = ['foo', 'déf'] + if sys.version_info[0] == 2: + # Check in Python 2 that the str (bytes object) with the non-ascii + # character has the encoding we expect. (This comes from the source + # code encoding at the top of the file.) + assert cmd_args[1].decode('utf-8') == u'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(u"""\ + Command errored out with exit status 1: + command: foo 'déf' + cwd: /path/to/cwd + Complete output (0 lines): + ----------------------------------------""") + assert actual == expected, u'actual: {}'.format(actual) + + +@pytest.mark.skipif("sys.version_info < (3,)") +def test_make_subprocess_output_error__non_ascii_cwd_python_3(monkeypatch): + """ + 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, 'actual: {}'.format(actual) + + +@pytest.mark.parametrize('encoding', [ + 'utf-8', + # Test a Windows encoding. + 'cp1252', +]) +@pytest.mark.skipif("sys.version_info >= (3,)") +def test_make_subprocess_output_error__non_ascii_cwd_python_2( + monkeypatch, encoding, +): + """ + Test a str (bytes object) cwd with a non-ascii character in Python 2. + """ + cmd_args = ['test'] + cwd = u'/path/to/cwd/déf'.encode(encoding) + monkeypatch.setattr(sys, 'getfilesystemencoding', lambda: encoding) + actual = make_subprocess_output_error( + cmd_args=cmd_args, + cwd=cwd, + lines=[], + exit_status=1, + ) + expected = dedent(u"""\ + Command errored out with exit status 1: + command: test + cwd: /path/to/cwd/déf + Complete output (0 lines): + ----------------------------------------""") + assert actual == expected, u'actual: {}'.format(actual) + + +# This test is mainly important for checking unicode in Python 2. +def test_make_subprocess_output_error__non_ascii_line(): + """ + Test a line with a non-ascii character. + """ + 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): + self.spin_count = 0 + self.final_status = None + + def spin(self): + self.spin_count += 1 + + def finish(self, final_status): + self.final_status = final_status + + +class TestCallSubprocess(object): + + """ + Test call_subprocess(). + """ + + def check_result( + self, capfd, caplog, log_level, spinner, result, expected, + expected_spinner, + ): + """ + Check the result of calling call_subprocess(). + + :param log_level: the logging level that caplog was set to. + :param spinner: the FakeSpinner object passed to call_subprocess() + to be checked. + :param result: the call_subprocess() return value to be checked. + :param expected: a pair (expected_proc, expected_records), where + 1) `expected_proc` is the expected return value of + call_subprocess() as a list of lines, or None if the return + value is expected to be None; + 2) `expected_records` is the expected value of + caplog.record_tuples. + :param expected_spinner: a 2-tuple of the spinner's expected + (spin_count, final_status). + """ + expected_proc, expected_records = expected + + if expected_proc is None: + assert result is None + else: + assert result.splitlines() == expected_proc + + # Confirm that stdout and stderr haven't been written to. + captured = capfd.readouterr() + assert (captured.out, captured.err) == ('', '') + + records = caplog.record_tuples + if len(records) != len(expected_records): + raise RuntimeError('{} != {}'.format(records, expected_records)) + + for record, expected_record in zip(records, expected_records): + # Check the logger_name and log level parts exactly. + assert record[:2] == expected_record[:2] + # For the message portion, check only a substring. Also, we + # can't use startswith() since the order of stdout and stderr + # isn't guaranteed in cases where stderr is also present. + # For example, we observed the stderr lines coming before stdout + # in CI for PyPy 2.7 even though stdout happens first + # chronologically. + assert expected_record[2] in record[2] + + assert (spinner.spin_count, spinner.final_status) == expected_spinner + + def prepare_call(self, caplog, log_level, command=None): + if command is None: + command = 'print("Hello"); print("world")' + + caplog.set_level(log_level) + spinner = FakeSpinner() + args = [sys.executable, '-c', command] + + return (args, spinner) + + def test_debug_logging(self, capfd, caplog): + """ + Test DEBUG logging (and without passing show_stdout=True). + """ + log_level = DEBUG + args, spinner = self.prepare_call(caplog, log_level) + result = call_subprocess(args, spinner=spinner) + + expected = (['Hello', 'world'], [ + ('pip.subprocessor', DEBUG, 'Running command '), + ('pip.subprocessor', DEBUG, 'Hello'), + ('pip.subprocessor', DEBUG, 'world'), + ]) + # The spinner shouldn't spin in this case since the subprocess + # output is already being logged to the console. + self.check_result( + capfd, caplog, log_level, spinner, result, expected, + expected_spinner=(0, None), + ) + + def test_info_logging(self, capfd, caplog): + """ + Test INFO logging (and without passing show_stdout=True). + """ + log_level = INFO + args, spinner = self.prepare_call(caplog, log_level) + result = call_subprocess(args, spinner=spinner) + + expected = (['Hello', 'world'], []) + # The spinner should spin twice in this case since the subprocess + # output isn't being written to the console. + self.check_result( + capfd, caplog, log_level, spinner, result, expected, + expected_spinner=(2, 'done'), + ) + + def test_info_logging__subprocess_error(self, capfd, caplog): + """ + Test INFO logging of a subprocess with an error (and without passing + show_stdout=True). + """ + log_level = INFO + command = 'print("Hello"); print("world"); exit("fail")' + args, spinner = self.prepare_call(caplog, log_level, command=command) + + 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 (3 lines):\n'), + ]) + # The spinner should spin three times in this case since the + # subprocess output isn't being written to the console. + self.check_result( + capfd, caplog, log_level, spinner, result, expected, + 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', + ], '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): + """ + Test INFO logging with show_stdout=True. + """ + log_level = INFO + args, spinner = self.prepare_call(caplog, log_level) + result = call_subprocess(args, spinner=spinner, show_stdout=True) + + expected = (['Hello', 'world'], [ + ('pip.subprocessor', INFO, 'Running command '), + ('pip.subprocessor', INFO, 'Hello'), + ('pip.subprocessor', INFO, 'world'), + ]) + # The spinner shouldn't spin in this case since the subprocess + # output is already being written to the console. + self.check_result( + capfd, caplog, log_level, spinner, result, expected, + expected_spinner=(0, None), + ) + + @pytest.mark.parametrize(( + 'exit_status', 'show_stdout', 'extra_ok_returncodes', 'log_level', + 'expected'), + [ + # The spinner should show here because show_stdout=False means + # the subprocess should get logged at DEBUG level, but the passed + # log level is only INFO. + (0, False, None, INFO, (None, 'done', 2)), + # Test some cases where the spinner should not be shown. + (0, False, None, DEBUG, (None, None, 0)), + # Test show_stdout=True. + (0, True, None, DEBUG, (None, None, 0)), + (0, True, None, INFO, (None, None, 0)), + # The spinner should show here because show_stdout=True means + # the subprocess should get logged at INFO level, but the passed + # log level is only WARNING. + (0, True, None, WARNING, (None, 'done', 2)), + # Test a non-zero exit status. + (3, False, None, INFO, (InstallationError, 'error', 2)), + # Test a non-zero exit status also in extra_ok_returncodes. + (3, False, (3, ), INFO, (None, 'done', 2)), + ]) + def test_spinner_finish( + self, exit_status, show_stdout, extra_ok_returncodes, log_level, + caplog, expected, + ): + """ + Test that the spinner finishes correctly. + """ + expected_exc_type = expected[0] + expected_final_status = expected[1] + expected_spin_count = expected[2] + + command = ( + 'print("Hello"); print("world"); exit({})'.format(exit_status) + ) + args, spinner = self.prepare_call(caplog, log_level, command=command) + try: + call_subprocess( + args, + show_stdout=show_stdout, + extra_ok_returncodes=extra_ok_returncodes, + spinner=spinner, + ) + except Exception as exc: + exc_type = type(exc) + else: + exc_type = None + + assert exc_type == expected_exc_type + assert spinner.final_status == expected_final_status + assert spinner.spin_count == expected_spin_count + + def test_closes_stdin(self): + with pytest.raises(InstallationError): + call_subprocess( + [sys.executable, '-c', 'input()'], + show_stdout=True, + ) From 27fdffbab6d5054ff4d6657874b5ff53a06f9f8a Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sun, 29 Sep 2019 09:30:37 +0530 Subject: [PATCH 4/8] Remove dependency of utils.logging on utils.suprocess --- src/pip/_internal/utils/logging.py | 4 ++-- src/pip/_internal/utils/subprocess.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 03725b0c1dd..7767111a6ba 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -9,14 +9,13 @@ import logging.handlers import os import sys -from logging import Filter +from logging import Filter, getLogger from pip._vendor.six import PY2 from pip._internal.utils.compat import WINDOWS from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX from pip._internal.utils.misc import ensure_dir -from pip._internal.utils.subprocess import subprocess_logger try: import threading @@ -54,6 +53,7 @@ _log_state = threading.local() _log_state.indentation = 0 +subprocess_logger = getLogger('pip.subprocessor') class BrokenStdoutLoggingError(Exception): diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 135c9b09a5f..3e2ad301cca 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -11,6 +11,7 @@ from pip._internal.exceptions import InstallationError from pip._internal.utils.compat import console_to_str, str_to_display +from pip._internal.utils.logging import subprocess_logger from pip._internal.utils.misc import HiddenText, path_to_display from pip._internal.utils.typing import MYPY_CHECK_RUNNING @@ -21,7 +22,6 @@ CommandArgs = List[Union[str, HiddenText]] -subprocess_logger = logging.getLogger('pip.subprocessor') LOG_DIVIDER = '----------------------------------------' From 46bd454e3e6ea1739594b554082c991b565aa283 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sat, 28 Sep 2019 12:38:22 +0530 Subject: [PATCH 5/8] Use pep517.Pep517HookCaller.subprocess_runner Also, create a new utility function for showing a spinner when running a subprocess. Why: The subprocess_runner API was specifically added to make it possible for pip to stop monkey-patching Pep517HookCaller, while still maintaining its output style. The relevant monkeypatch will be removed in a follow up commit. --- .../_internal/distributions/source/legacy.py | 11 +++++-- src/pip/_internal/req/req_install.py | 16 ++++++---- src/pip/_internal/utils/subprocess.py | 30 ++++++++++++++++++- src/pip/_internal/wheel.py | 14 ++++++--- 4 files changed, 57 insertions(+), 14 deletions(-) diff --git a/src/pip/_internal/distributions/source/legacy.py b/src/pip/_internal/distributions/source/legacy.py index ae1d9b40b68..5651bc5c61b 100644 --- a/src/pip/_internal/distributions/source/legacy.py +++ b/src/pip/_internal/distributions/source/legacy.py @@ -6,6 +6,7 @@ from pip._internal.build_env import BuildEnvironment from pip._internal.distributions.base import AbstractDistribution from pip._internal.exceptions import InstallationError +from pip._internal.utils.subprocess import run_with_spinner_message logger = logging.getLogger(__name__) @@ -81,9 +82,13 @@ def _raise_conflicts(conflicting_with, conflicting_reqs): # This must be done in a second pass, as the pyproject.toml # dependencies must be installed before we can call the backend. with self.req.build_env: - # We need to have the env active when calling the hook. - self.req.spin_message = "Getting requirements to build wheel" - reqs = self.req.pep517_backend.get_requires_for_build_wheel() + runner = run_with_spinner_message( + "Getting requirements to build wheel" + ) + backend = self.req.pep517_backend + with backend.subprocess_runner(runner): + reqs = backend.get_requires_for_build_wheel() + conflicting, missing = self.req.build_env.check_requirements(reqs) if conflicting: _raise_conflicts("the backend dependencies", conflicting) diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index c578bf22593..6f13bc05ded 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -49,7 +49,10 @@ ) from pip._internal.utils.packaging import get_metadata from pip._internal.utils.setuptools_build import make_setuptools_shim_args -from pip._internal.utils.subprocess import call_subprocess +from pip._internal.utils.subprocess import ( + call_subprocess, + run_with_spinner_message, +) from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING from pip._internal.utils.ui import open_spinner @@ -58,7 +61,7 @@ if MYPY_CHECK_RUNNING: from typing import ( - Any, Dict, Iterable, List, Mapping, Optional, Sequence, Union, + Any, Dict, Iterable, List, Optional, Sequence, Union, ) from pip._internal.build_env import BuildEnvironment from pip._internal.cache import WheelCache @@ -622,11 +625,12 @@ def prepare_pep517_metadata(self): # Note that Pep517HookCaller implements a fallback for # prepare_metadata_for_build_wheel, so we don't have to # consider the possibility that this hook doesn't exist. + runner = run_with_spinner_message("Preparing wheel metadata") backend = self.pep517_backend - self.spin_message = "Preparing wheel metadata" - distinfo_dir = backend.prepare_metadata_for_build_wheel( - metadata_dir - ) + with backend.subprocess_runner(runner): + distinfo_dir = backend.prepare_metadata_for_build_wheel( + metadata_dir + ) return os.path.join(metadata_dir, distinfo_dir) diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 3e2ad301cca..7a0bedf16fc 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -14,9 +14,12 @@ from pip._internal.utils.logging import subprocess_logger from pip._internal.utils.misc import HiddenText, path_to_display from pip._internal.utils.typing import MYPY_CHECK_RUNNING +from pip._internal.utils.ui import open_spinner if MYPY_CHECK_RUNNING: - from typing import Any, Iterable, List, Mapping, Optional, Text, Union + from typing import ( + Any, Callable, Iterable, List, Mapping, Optional, Text, Union, + ) from pip._internal.utils.ui import SpinnerInterface CommandArgs = List[Union[str, HiddenText]] @@ -245,3 +248,28 @@ def call_subprocess( raise ValueError('Invalid value: on_returncode=%s' % repr(on_returncode)) return ''.join(all_output) + + +def run_with_spinner_message(message): + # type: (str) -> Callable + """Provide a subprocess_runner that shows a spinner message. + + Intended for use with for pep517's Pep517HookCaller. Thus, the runner has + an API that matches what's expected by Pep517HookCaller.subprocess_runner. + """ + + def runner( + cmd, # type: List[str] + cwd=None, # type: Optional[str] + extra_environ=None # type: Optional[Mapping[str, Any]] + ): + # type: (...) -> None + with open_spinner(message) as spinner: + call_subprocess( + cmd, + cwd=cwd, + extra_environ=extra_environ, + spinner=spinner, + ) + + return runner diff --git a/src/pip/_internal/wheel.py b/src/pip/_internal/wheel.py index 7d6a4773dbf..7c37a70c031 100644 --- a/src/pip/_internal/wheel.py +++ b/src/pip/_internal/wheel.py @@ -44,6 +44,7 @@ LOG_DIVIDER, call_subprocess, format_command_args, + run_with_spinner_message, ) from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING @@ -979,12 +980,17 @@ def _build_one_pep517(self, req, tempd, python_tag=None): '--build-options is present' % (req.name,)) return None try: - req.spin_message = 'Building wheel for %s (PEP 517)' % (req.name,) logger.debug('Destination directory: %s', tempd) - wheel_name = req.pep517_backend.build_wheel( - tempd, - metadata_directory=req.metadata_directory + + runner = run_with_spinner_message( + 'Building wheel for {} (PEP 517)'.format(req.name) ) + backend = req.pep517_backend + with backend.subprocess_runner(runner): + wheel_name = backend.build_wheel( + tempd, + metadata_directory=req.metadata_directory, + ) if python_tag: # General PEP 517 backends don't necessarily support # a "--python-tag" option, so we rename the wheel From 489312e4d9e334abd38fdca97214540c4cd5599e Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sat, 28 Sep 2019 12:38:56 +0530 Subject: [PATCH 6/8] Stop monkeypatching InstallRequirement.pep517_backend --- src/pip/_internal/req/req_install.py | 20 -------------------- 1 file changed, 20 deletions(-) diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index 6f13bc05ded..8b86238063b 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -550,26 +550,6 @@ def load_pyproject_toml(self): self.unpacked_source_directory, backend ) - # Use a custom function to call subprocesses - self.spin_message = "" - - def runner( - cmd, # type: List[str] - cwd=None, # type: Optional[str] - extra_environ=None # type: Optional[Mapping[str, Any]] - ): - # type: (...) -> None - with open_spinner(self.spin_message) as spinner: - call_subprocess( - cmd, - cwd=cwd, - extra_environ=extra_environ, - spinner=spinner - ) - self.spin_message = "" - - self.pep517_backend._subprocess_runner = runner - def prepare_metadata(self): # type: () -> None """Ensure that project metadata is available. From 65621002fc596bba112ce0db5d768a10f5832a54 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Sun, 29 Sep 2019 11:25:01 +0530 Subject: [PATCH 7/8] Use run_with_spinner_message() for "setup.py install" --- src/pip/_internal/req/req_install.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index 8b86238063b..4ef776eaa43 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -55,7 +55,6 @@ ) from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING -from pip._internal.utils.ui import open_spinner from pip._internal.utils.virtualenv import running_under_virtualenv from pip._internal.vcs import vcs @@ -935,15 +934,15 @@ def install( install_args = self.get_install_args( global_options, record_filename, root, prefix, pycompile, ) - msg = 'Running setup.py install for %s' % (self.name,) - with open_spinner(msg) as spinner: - with indent_log(): - with self.build_env: - call_subprocess( - install_args + install_options, - cwd=self.unpacked_source_directory, - spinner=spinner, - ) + + runner = run_with_spinner_message( + "Running setup.py install for {}".format(self.name) + ) + with indent_log(), self.build_env: + runner( + cmd=install_args + install_options, + cwd=self.unpacked_source_directory, + ) if not os.path.exists(record_filename): logger.debug('Record file %s not found', record_filename) From 1ad0495fdd61c3c1fa67645558c4dec5751c21e1 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Mon, 30 Sep 2019 12:06:05 +0530 Subject: [PATCH 8/8] Rename {run -> runner}_with_spinner_message --- src/pip/_internal/distributions/source/legacy.py | 4 ++-- src/pip/_internal/req/req_install.py | 6 +++--- src/pip/_internal/utils/subprocess.py | 2 +- src/pip/_internal/wheel.py | 4 ++-- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/pip/_internal/distributions/source/legacy.py b/src/pip/_internal/distributions/source/legacy.py index 5651bc5c61b..ab43afbec84 100644 --- a/src/pip/_internal/distributions/source/legacy.py +++ b/src/pip/_internal/distributions/source/legacy.py @@ -6,7 +6,7 @@ from pip._internal.build_env import BuildEnvironment from pip._internal.distributions.base import AbstractDistribution from pip._internal.exceptions import InstallationError -from pip._internal.utils.subprocess import run_with_spinner_message +from pip._internal.utils.subprocess import runner_with_spinner_message logger = logging.getLogger(__name__) @@ -82,7 +82,7 @@ def _raise_conflicts(conflicting_with, conflicting_reqs): # This must be done in a second pass, as the pyproject.toml # dependencies must be installed before we can call the backend. with self.req.build_env: - runner = run_with_spinner_message( + runner = runner_with_spinner_message( "Getting requirements to build wheel" ) backend = self.req.pep517_backend diff --git a/src/pip/_internal/req/req_install.py b/src/pip/_internal/req/req_install.py index 4ef776eaa43..c59a4166ecd 100644 --- a/src/pip/_internal/req/req_install.py +++ b/src/pip/_internal/req/req_install.py @@ -51,7 +51,7 @@ from pip._internal.utils.setuptools_build import make_setuptools_shim_args from pip._internal.utils.subprocess import ( call_subprocess, - run_with_spinner_message, + runner_with_spinner_message, ) from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING @@ -604,7 +604,7 @@ def prepare_pep517_metadata(self): # Note that Pep517HookCaller implements a fallback for # prepare_metadata_for_build_wheel, so we don't have to # consider the possibility that this hook doesn't exist. - runner = run_with_spinner_message("Preparing wheel metadata") + runner = runner_with_spinner_message("Preparing wheel metadata") backend = self.pep517_backend with backend.subprocess_runner(runner): distinfo_dir = backend.prepare_metadata_for_build_wheel( @@ -935,7 +935,7 @@ def install( global_options, record_filename, root, prefix, pycompile, ) - runner = run_with_spinner_message( + runner = runner_with_spinner_message( "Running setup.py install for {}".format(self.name) ) with indent_log(), self.build_env: diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 7a0bedf16fc..ddb418d2467 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -250,7 +250,7 @@ def call_subprocess( return ''.join(all_output) -def run_with_spinner_message(message): +def runner_with_spinner_message(message): # type: (str) -> Callable """Provide a subprocess_runner that shows a spinner message. diff --git a/src/pip/_internal/wheel.py b/src/pip/_internal/wheel.py index 7c37a70c031..8f9778c7d29 100644 --- a/src/pip/_internal/wheel.py +++ b/src/pip/_internal/wheel.py @@ -44,7 +44,7 @@ LOG_DIVIDER, call_subprocess, format_command_args, - run_with_spinner_message, + runner_with_spinner_message, ) from pip._internal.utils.temp_dir import TempDirectory from pip._internal.utils.typing import MYPY_CHECK_RUNNING @@ -982,7 +982,7 @@ def _build_one_pep517(self, req, tempd, python_tag=None): try: logger.debug('Destination directory: %s', tempd) - runner = run_with_spinner_message( + runner = runner_with_spinner_message( 'Building wheel for {} (PEP 517)'.format(req.name) ) backend = req.pep517_backend