From 6480bed441a03d6346b9439112ee4b9aeee7cbc4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 12:38:41 +0100 Subject: [PATCH 1/9] Revert "Remove on_returncode parameter from call_subprocess" This reverts commit ab3ee7191ca47294f8827916180969e23f5e0381. --- src/pip/_internal/vcs/git.py | 10 ++---- src/pip/_internal/vcs/mercurial.py | 1 + src/pip/_internal/vcs/versioncontrol.py | 42 ++++++++++++++++--------- 3 files changed, 32 insertions(+), 21 deletions(-) diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index 1831aede5..141263803 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -135,13 +135,8 @@ class Git(VersionControl): rev: the revision name. """ # Pass rev to pre-filter the list. - - output = '' - try: - output = cls.run_command(['show-ref', rev], cwd=dest) - except SubProcessError: - pass - + output = cls.run_command(['show-ref', rev], cwd=dest, + on_returncode='ignore') refs = {} for line in output.strip().splitlines(): try: @@ -420,6 +415,7 @@ class Git(VersionControl): r = cls.run_command( ['rev-parse', '--show-toplevel'], cwd=location, + on_returncode='raise', log_failed_cmd=False, ) except BadCommand: diff --git a/src/pip/_internal/vcs/mercurial.py b/src/pip/_internal/vcs/mercurial.py index 69763feae..b7f8073fd 100644 --- a/src/pip/_internal/vcs/mercurial.py +++ b/src/pip/_internal/vcs/mercurial.py @@ -144,6 +144,7 @@ class Mercurial(VersionControl): r = cls.run_command( ['root'], cwd=location, + on_returncode='raise', log_failed_cmd=False, ) except BadCommand: diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index 6724dcc69..5b93b6609 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -90,6 +90,7 @@ def make_vcs_requirement_url(repo_url, rev, project_name, subdir=None): def call_subprocess( cmd, # type: Union[List[str], CommandArgs] cwd=None, # type: Optional[str] + on_returncode='raise', # type: str extra_environ=None, # type: Optional[Mapping[str, Any]] extra_ok_returncodes=None, # type: Optional[Iterable[int]] log_failed_cmd=True # type: Optional[bool] @@ -157,21 +158,32 @@ def call_subprocess( proc.returncode and proc.returncode not in extra_ok_returncodes ) if proc_had_error: - 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, + 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, + ) + 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 SubProcessError(exc_msg) + elif on_returncode == 'warn': + subprocess_logger.warning( + 'Command "{}" had error code {} in {}'.format( + 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 SubProcessError(exc_msg) + elif on_returncode == 'ignore': + pass + else: + raise ValueError('Invalid value: on_returncode={!r}'.format( + on_returncode)) return ''.join(all_output) @@ -764,6 +776,7 @@ class VersionControl(object): cls, cmd, # type: Union[List[str], CommandArgs] cwd=None, # type: Optional[str] + on_returncode='raise', # type: str extra_environ=None, # type: Optional[Mapping[str, Any]] extra_ok_returncodes=None, # type: Optional[Iterable[int]] log_failed_cmd=True # type: bool @@ -777,6 +790,7 @@ class VersionControl(object): cmd = make_command(cls.name, *cmd) try: return call_subprocess(cmd, cwd, + on_returncode=on_returncode, extra_environ=extra_environ, extra_ok_returncodes=extra_ok_returncodes, log_failed_cmd=log_failed_cmd) From 6693a71e0a472533714351b46aed688e19a17874 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 12:44:23 +0100 Subject: [PATCH 2/9] Revert "Remove show_stdout from run_command args" This reverts commit 94882fd1ed9171ea5a2f4b8904dbd8763f05ba68. --- src/pip/_internal/vcs/bazaar.py | 7 ++-- src/pip/_internal/vcs/git.py | 19 +++++----- src/pip/_internal/vcs/mercurial.py | 16 ++++---- src/pip/_internal/vcs/subversion.py | 9 +++-- src/pip/_internal/vcs/versioncontrol.py | 50 +++++++++++++++++-------- 5 files changed, 62 insertions(+), 39 deletions(-) diff --git a/src/pip/_internal/vcs/bazaar.py b/src/pip/_internal/vcs/bazaar.py index 3180713f7..efe524492 100644 --- a/src/pip/_internal/vcs/bazaar.py +++ b/src/pip/_internal/vcs/bazaar.py @@ -55,7 +55,8 @@ class Bazaar(VersionControl): url, rev_options = self.get_url_rev_options(url) self.run_command( - make_command('export', location, url, rev_options.to_args()) + make_command('export', location, url, rev_options.to_args()), + show_stdout=False, ) def fetch_new(self, dest, url, rev_options): @@ -92,7 +93,7 @@ class Bazaar(VersionControl): @classmethod def get_remote_url(cls, location): - urls = cls.run_command(['info'], cwd=location) + urls = cls.run_command(['info'], show_stdout=False, cwd=location) for line in urls.splitlines(): line = line.strip() for x in ('checkout of branch: ', @@ -107,7 +108,7 @@ class Bazaar(VersionControl): @classmethod def get_revision(cls, location): revision = cls.run_command( - ['revno'], cwd=location, + ['revno'], show_stdout=False, cwd=location, ) return revision.splitlines()[-1] diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index 141263803..a6d1396fc 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -11,7 +11,7 @@ from pip._vendor.packaging.version import parse as parse_version from pip._vendor.six.moves.urllib import parse as urllib_parse from pip._vendor.six.moves.urllib import request as urllib_request -from pip._internal.exceptions import BadCommand, SubProcessError +from pip._internal.exceptions import BadCommand, InstallationError, SubProcessError from pip._internal.utils.misc import display_path, hide_url from pip._internal.utils.subprocess import make_command from pip._internal.utils.temp_dir import TempDirectory @@ -79,7 +79,7 @@ class Git(VersionControl): def get_git_version(self): VERSION_PFX = 'git version ' - version = self.run_command(['version']) + version = self.run_command(['version'], show_stdout=False) if version.startswith(VERSION_PFX): version = version[len(VERSION_PFX):].split()[0] else: @@ -102,7 +102,7 @@ class Git(VersionControl): # and to suppress the message to stderr. args = ['symbolic-ref', '-q', 'HEAD'] output = cls.run_command( - args, extra_ok_returncodes=(1, ), cwd=location, + args, extra_ok_returncodes=(1, ), show_stdout=False, cwd=location, ) ref = output.strip() @@ -121,7 +121,7 @@ class Git(VersionControl): self.unpack(temp_dir.path, url=url) self.run_command( ['checkout-index', '-a', '-f', '--prefix', location], - cwd=temp_dir.path + show_stdout=False, cwd=temp_dir.path ) @classmethod @@ -136,7 +136,7 @@ class Git(VersionControl): """ # Pass rev to pre-filter the list. output = cls.run_command(['show-ref', rev], cwd=dest, - on_returncode='ignore') + show_stdout=False, on_returncode='ignore') refs = {} for line in output.strip().splitlines(): try: @@ -310,7 +310,7 @@ class Git(VersionControl): # exits with return code 1 if there are no matching lines. stdout = cls.run_command( ['config', '--get-regexp', r'remote\..*\.url'], - extra_ok_returncodes=(1, ), cwd=location, + extra_ok_returncodes=(1, ), show_stdout=False, cwd=location, ) remotes = stdout.splitlines() try: @@ -344,7 +344,7 @@ class Git(VersionControl): if rev is None: rev = 'HEAD' current_rev = cls.run_command( - ['rev-parse', rev], cwd=location, + ['rev-parse', rev], show_stdout=False, cwd=location, ) return current_rev.strip() @@ -357,7 +357,7 @@ class Git(VersionControl): # find the repo root git_dir = cls.run_command( ['rev-parse', '--git-dir'], - cwd=location).strip() + show_stdout=False, cwd=location).strip() if not os.path.isabs(git_dir): git_dir = os.path.join(location, git_dir) repo_root = os.path.abspath(os.path.join(git_dir, '..')) @@ -415,6 +415,7 @@ class Git(VersionControl): r = cls.run_command( ['rev-parse', '--show-toplevel'], cwd=location, + show_stdout=False, on_returncode='raise', log_failed_cmd=False, ) @@ -422,7 +423,7 @@ class Git(VersionControl): logger.debug("could not determine if %s is under git control " "because git is not available", location) return None - except SubProcessError: + except InstallationError: return None return os.path.normpath(r.rstrip('\r\n')) diff --git a/src/pip/_internal/vcs/mercurial.py b/src/pip/_internal/vcs/mercurial.py index b7f8073fd..75e903cc8 100644 --- a/src/pip/_internal/vcs/mercurial.py +++ b/src/pip/_internal/vcs/mercurial.py @@ -8,7 +8,7 @@ import os from pip._vendor.six.moves import configparser -from pip._internal.exceptions import BadCommand, SubProcessError +from pip._internal.exceptions import BadCommand, InstallationError from pip._internal.utils.misc import display_path from pip._internal.utils.subprocess import make_command from pip._internal.utils.temp_dir import TempDirectory @@ -47,7 +47,7 @@ class Mercurial(VersionControl): self.unpack(temp_dir.path, url=url) self.run_command( - ['archive', location], cwd=temp_dir.path + ['archive', location], show_stdout=False, cwd=temp_dir.path ) def fetch_new(self, dest, url, rev_options): @@ -92,7 +92,7 @@ class Mercurial(VersionControl): def get_remote_url(cls, location): url = cls.run_command( ['showconfig', 'paths.default'], - cwd=location).strip() + show_stdout=False, cwd=location).strip() if cls._is_local_repository(url): url = path_to_url(url) return url.strip() @@ -103,7 +103,8 @@ class Mercurial(VersionControl): Return the repository-local changeset revision number, as an integer. """ current_revision = cls.run_command( - ['parents', '--template={rev}'], cwd=location).strip() + ['parents', '--template={rev}'], + show_stdout=False, cwd=location).strip() return current_revision @classmethod @@ -114,7 +115,7 @@ class Mercurial(VersionControl): """ current_rev_hash = cls.run_command( ['parents', '--template={node}'], - cwd=location).strip() + show_stdout=False, cwd=location).strip() return current_rev_hash @classmethod @@ -130,7 +131,7 @@ class Mercurial(VersionControl): """ # find the repo root repo_root = cls.run_command( - ['root'], cwd=location).strip() + ['root'], show_stdout=False, cwd=location).strip() if not os.path.isabs(repo_root): repo_root = os.path.abspath(os.path.join(location, repo_root)) return find_path_to_setup_from_repo_root(location, repo_root) @@ -144,6 +145,7 @@ class Mercurial(VersionControl): r = cls.run_command( ['root'], cwd=location, + show_stdout=False, on_returncode='raise', log_failed_cmd=False, ) @@ -151,7 +153,7 @@ class Mercurial(VersionControl): logger.debug("could not determine if %s is under hg control " "because hg is not available", location) return None - except SubProcessError: + except InstallationError: return None return os.path.normpath(r.rstrip('\r\n')) diff --git a/src/pip/_internal/vcs/subversion.py b/src/pip/_internal/vcs/subversion.py index eae09c196..a57e19751 100644 --- a/src/pip/_internal/vcs/subversion.py +++ b/src/pip/_internal/vcs/subversion.py @@ -133,7 +133,7 @@ class Subversion(VersionControl): @classmethod def _get_svn_url_rev(cls, location): - from pip._internal.exceptions import SubProcessError + from pip._internal.exceptions import InstallationError entries_path = os.path.join(location, cls.dirname, 'entries') if os.path.exists(entries_path): @@ -166,12 +166,13 @@ class Subversion(VersionControl): # are only potentially needed for remote server requests. xml = cls.run_command( ['info', '--xml', location], + show_stdout=False, ) url = _svn_info_xml_url_re.search(xml).group(1) revs = [ int(m.group(1)) for m in _svn_info_xml_rev_re.finditer(xml) ] - except SubProcessError: + except InstallationError: url, revs = None, [] if revs: @@ -217,7 +218,7 @@ class Subversion(VersionControl): # svn, version 1.12.0-SlikSvn (SlikSvn/1.12.0) # compiled May 28 2019, 13:44:56 on x86_64-microsoft-windows6.2 version_prefix = 'svn, version ' - version = self.run_command(['--version']) + version = self.run_command(['--version'], show_stdout=True) if not version.startswith(version_prefix): return () @@ -300,7 +301,7 @@ class Subversion(VersionControl): 'export', self.get_remote_call_options(), rev_options.to_args(), url, location, ) - self.run_command(cmd_args) + self.run_command(cmd_args, show_stdout=False) def fetch_new(self, dest, url, rev_options): # type: (str, HiddenText, RevOptions) -> None diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index 5b93b6609..a4995c88f 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -34,12 +34,10 @@ from pip._internal.utils.urls import get_url_scheme if MYPY_CHECK_RUNNING: from typing import ( - Any, Dict, Iterable, Iterator, List, - Mapping, Optional, Text, Tuple, @@ -89,15 +87,17 @@ def make_vcs_requirement_url(repo_url, rev, project_name, subdir=None): 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_environ=None, # type: Optional[Mapping[str, Any]] extra_ok_returncodes=None, # type: Optional[Iterable[int]] log_failed_cmd=True # type: Optional[bool] ): # 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 []. log_failed_cmd: if false, failed commands are not logged, @@ -105,16 +105,33 @@ def call_subprocess( """ if extra_ok_returncodes is None: extra_ok_returncodes = [] - - # log the subprocess output at DEBUG level. - log_subprocess = subprocess_logger.debug - - env = os.environ.copy() - if extra_environ: - env.update(extra_environ) + # Most places in pip use show_stdout=False. + # What this means is-- + # + # - We log this output of stdout and 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 = True + showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level command_desc = format_command_args(cmd) try: @@ -176,8 +193,10 @@ def call_subprocess( raise SubProcessError(exc_msg) elif on_returncode == 'warn': subprocess_logger.warning( - 'Command "{}" had error code {} in {}'.format( - command_desc, proc.returncode, cwd) + 'Command "%s" had error code %s in %s', + command_desc, + proc.returncode, + cwd, ) elif on_returncode == 'ignore': pass @@ -775,9 +794,9 @@ class VersionControl(object): def run_command( cls, cmd, # type: Union[List[str], CommandArgs] + show_stdout=True, # type: bool cwd=None, # type: Optional[str] on_returncode='raise', # type: str - extra_environ=None, # type: Optional[Mapping[str, Any]] extra_ok_returncodes=None, # type: Optional[Iterable[int]] log_failed_cmd=True # type: bool ): @@ -789,9 +808,8 @@ class VersionControl(object): """ cmd = make_command(cls.name, *cmd) try: - return call_subprocess(cmd, cwd, + return call_subprocess(cmd, show_stdout, cwd, on_returncode=on_returncode, - extra_environ=extra_environ, extra_ok_returncodes=extra_ok_returncodes, log_failed_cmd=log_failed_cmd) except OSError as e: From eda67075c1669b298d82a9a0e4c5484d02ad41b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 13:03:11 +0100 Subject: [PATCH 3/9] Revert "Create call_subprocess just for vcs commands" This reverts commit 8adbc216a647b6b349f1b7f1eaa9e71cd3108955. --- src/pip/_internal/exceptions.py | 5 - src/pip/_internal/vcs/subversion.py | 14 ++- src/pip/_internal/vcs/versioncontrol.py | 144 +++--------------------- 3 files changed, 25 insertions(+), 138 deletions(-) diff --git a/src/pip/_internal/exceptions.py b/src/pip/_internal/exceptions.py index 56482caf7..5a2d012a5 100644 --- a/src/pip/_internal/exceptions.py +++ b/src/pip/_internal/exceptions.py @@ -91,11 +91,6 @@ class CommandError(PipError): """Raised when there is an error in command-line arguments""" -class SubProcessError(PipError): - """Raised when there is an error raised while executing a - command in subprocess""" - - class PreviousBuildDirError(PipError): """Raised when there's a previous conflicting build directory""" diff --git a/src/pip/_internal/vcs/subversion.py b/src/pip/_internal/vcs/subversion.py index a57e19751..2575872a7 100644 --- a/src/pip/_internal/vcs/subversion.py +++ b/src/pip/_internal/vcs/subversion.py @@ -25,7 +25,7 @@ _svn_info_xml_url_re = re.compile(r'(.*)') if MYPY_CHECK_RUNNING: - from typing import Optional, Tuple + from typing import Optional, Text, Tuple from pip._internal.utils.misc import HiddenText from pip._internal.utils.subprocess import CommandArgs @@ -218,7 +218,17 @@ class Subversion(VersionControl): # svn, version 1.12.0-SlikSvn (SlikSvn/1.12.0) # compiled May 28 2019, 13:44:56 on x86_64-microsoft-windows6.2 version_prefix = 'svn, version ' - version = self.run_command(['--version'], show_stdout=True) + cmd_output = self.run_command(['--version'], show_stdout=False) + + # Split the output by newline, and find the first line where + # version_prefix is present + output_lines = cmd_output.split('\n') + version = '' # type: Text + + for line in output_lines: + if version_prefix in line: + version = line + break if not version.startswith(version_prefix): return () diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index a4995c88f..1d9cb08fe 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -6,15 +6,13 @@ import errno import logging import os import shutil -import subprocess import sys from pip._vendor import pkg_resources from pip._vendor.six.moves.urllib import parse as urllib_parse -from pip._internal.exceptions import BadCommand, InstallationError, SubProcessError -from pip._internal.utils.compat import console_to_str, samefile -from pip._internal.utils.logging import subprocess_logger +from pip._internal.exceptions import BadCommand, InstallationError +from pip._internal.utils.compat import samefile from pip._internal.utils.misc import ( ask_path_exists, backup_dir, @@ -23,21 +21,18 @@ from pip._internal.utils.misc import ( hide_value, rmtree, ) -from pip._internal.utils.subprocess import ( - format_command_args, - make_command, - make_subprocess_output_error, - reveal_command_args, -) +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 if MYPY_CHECK_RUNNING: from typing import ( + Any, Dict, Iterable, Iterator, List, + Mapping, Optional, Text, Tuple, @@ -45,6 +40,7 @@ if MYPY_CHECK_RUNNING: Union, ) + from pip._internal.cli.spinners import SpinnerInterface from pip._internal.utils.misc import HiddenText from pip._internal.utils.subprocess import CommandArgs @@ -85,127 +81,6 @@ def make_vcs_requirement_url(repo_url, rev, project_name, subdir=None): return req -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]] - log_failed_cmd=True # type: Optional[bool] -): - # 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 []. - log_failed_cmd: if false, failed commands are not logged, - only raised. - """ - if extra_ok_returncodes is None: - extra_ok_returncodes = [] - # Most places in pip use show_stdout=False. - # What this means is-- - # - # - We log this output of stdout and 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 - - command_desc = format_command_args(cmd) - try: - proc = subprocess.Popen( - # Convert HiddenText objects to the underlying str. - reveal_command_args(cmd), - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - cwd=cwd - ) - if proc.stdin: - proc.stdin.close() - except Exception as exc: - if log_failed_cmd: - 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 = None - if proc.stdout: - 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) - try: - proc.wait() - finally: - if proc.stdout: - proc.stdout.close() - if proc.stderr: - proc.stderr.close() - - proc_had_error = ( - proc.returncode and proc.returncode not in extra_ok_returncodes - ) - 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, - ) - 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 SubProcessError(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={!r}'.format( - on_returncode)) - return ''.join(all_output) - - def find_path_to_setup_from_repo_root(location, repo_root): # type: (str, str) -> Optional[str] """ @@ -798,6 +673,9 @@ class VersionControl(object): 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]] + spinner=None, # type: Optional[SpinnerInterface] log_failed_cmd=True # type: bool ): # type: (...) -> Text @@ -811,6 +689,10 @@ class VersionControl(object): return call_subprocess(cmd, show_stdout, cwd, on_returncode=on_returncode, extra_ok_returncodes=extra_ok_returncodes, + command_desc=command_desc, + extra_environ=extra_environ, + unset_environ=cls.unset_environ, + spinner=spinner, log_failed_cmd=log_failed_cmd) except OSError as e: # errno.ENOENT = no such file or directory From 8665a3e1e2c6d95802ff351eb66fa59e0939e820 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 13:05:16 +0100 Subject: [PATCH 4/9] Revert "Improve check for svn version string" This reverts commit 1471897b84b43c467c753b5edebe636f835afc6a. --- src/pip/_internal/vcs/subversion.py | 15 ++------------- 1 file changed, 2 insertions(+), 13 deletions(-) diff --git a/src/pip/_internal/vcs/subversion.py b/src/pip/_internal/vcs/subversion.py index 2575872a7..b84108efc 100644 --- a/src/pip/_internal/vcs/subversion.py +++ b/src/pip/_internal/vcs/subversion.py @@ -25,7 +25,7 @@ _svn_info_xml_url_re = re.compile(r'(.*)') if MYPY_CHECK_RUNNING: - from typing import Optional, Text, Tuple + from typing import Optional, Tuple from pip._internal.utils.misc import HiddenText from pip._internal.utils.subprocess import CommandArgs @@ -218,18 +218,7 @@ class Subversion(VersionControl): # svn, version 1.12.0-SlikSvn (SlikSvn/1.12.0) # compiled May 28 2019, 13:44:56 on x86_64-microsoft-windows6.2 version_prefix = 'svn, version ' - cmd_output = self.run_command(['--version'], show_stdout=False) - - # Split the output by newline, and find the first line where - # version_prefix is present - output_lines = cmd_output.split('\n') - version = '' # type: Text - - for line in output_lines: - if version_prefix in line: - version = line - break - + version = self.run_command(['--version'], show_stdout=False) if not version.startswith(version_prefix): return () From 19039c27e99349ef627aef55280158baef557e0b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 15:07:48 +0100 Subject: [PATCH 5/9] Revert "Bubble up SubProcessError to basecommand._main" This reverts commit e9f738a3daec91b131ae985e16809d47b1cfdaff. --- src/pip/_internal/cli/base_command.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index 7f05efb85..41e7dcf10 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/src/pip/_internal/cli/base_command.py @@ -27,7 +27,6 @@ from pip._internal.exceptions import ( InstallationError, NetworkConnectionError, PreviousBuildDirError, - SubProcessError, UninstallationError, ) from pip._internal.utils.deprecation import deprecated @@ -230,7 +229,7 @@ class Command(CommandContextMixIn): return PREVIOUS_BUILD_DIR_ERROR except (InstallationError, UninstallationError, BadCommand, - SubProcessError, NetworkConnectionError) as exc: + NetworkConnectionError) as exc: logger.critical(str(exc)) logger.debug('Exception information:', exc_info=True) From bcc412c44aa59b5dd217dcd5b741bf2efec0962c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 13:33:46 +0100 Subject: [PATCH 6/9] Additional revert of 7969 Revert additional changes that were made after 7969 and depended on it. --- src/pip/_internal/vcs/git.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index a6d1396fc..de9c7f519 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -11,7 +11,7 @@ from pip._vendor.packaging.version import parse as parse_version from pip._vendor.six.moves.urllib import parse as urllib_parse from pip._vendor.six.moves.urllib import request as urllib_request -from pip._internal.exceptions import BadCommand, InstallationError, SubProcessError +from pip._internal.exceptions import BadCommand, InstallationError from pip._internal.utils.misc import display_path, hide_url from pip._internal.utils.subprocess import make_command from pip._internal.utils.temp_dir import TempDirectory @@ -332,9 +332,11 @@ class Git(VersionControl): """ try: cls.run_command( - ['rev-parse', '-q', '--verify', "sha^" + rev], cwd=location + ['rev-parse', '-q', '--verify', "sha^" + rev], + cwd=location, + log_failed_cmd=False, ) - except SubProcessError: + except InstallationError: return False else: return True From 139293b5e2541df764f7760f790f42cdb0d48621 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 14:39:50 +0100 Subject: [PATCH 7/9] add stdout_only to call_subprocess --- src/pip/_internal/utils/subprocess.py | 69 ++++++++++++++++++--------- 1 file changed, 47 insertions(+), 22 deletions(-) diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 605e711e6..3c79c7289 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -118,7 +118,8 @@ def call_subprocess( extra_environ=None, # type: Optional[Mapping[str, Any]] unset_environ=None, # type: Optional[Iterable[str]] spinner=None, # type: Optional[SpinnerInterface] - log_failed_cmd=True # type: Optional[bool] + log_failed_cmd=True, # type: Optional[bool] + stdout_only=False, # type: Optional[bool] ): # type: (...) -> Text """ @@ -130,6 +131,9 @@ def call_subprocess( unset_environ: an iterable of environment variable names to unset prior to calling subprocess.Popen(). log_failed_cmd: if false, failed commands are not logged, only raised. + stdout_only: if true, return only stdout, else return both. When true, + logging of both stdout and stderr occurs when the subprocess has + terminated, else logging occurs as subprocess output is produced. """ if extra_ok_returncodes is None: extra_ok_returncodes = [] @@ -180,8 +184,11 @@ def call_subprocess( 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, + stdin=subprocess.PIPE, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT if not stdout_only else subprocess.PIPE, + cwd=cwd, + env=env, ) assert proc.stdin assert proc.stdout @@ -193,25 +200,43 @@ 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 - line = line.rstrip() - all_output.append(line + '\n') + if not stdout_only: + # In this mode, stdout and stderr are in the same pip. + 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: + assert spinner + spinner.spin() + try: + proc.wait() + finally: + if proc.stdout: + proc.stdout.close() + output = ''.join(all_output) + else: + # In this mode, stdout and stderr are in different pipes. + # We must use the communicate which is the only safe way to read both. + out_bytes, err_bytes = proc.communicate() + # log line by line to preserve pip log indenting + out = console_to_str(out_bytes) + for out_line in out.splitlines(): + log_subprocess(out_line) + all_output.append(out) + err = console_to_str(err_bytes) + for err_line in err.splitlines(): + log_subprocess(err_line) + all_output.append(err) + output = out - # Show the line immediately. - log_subprocess(line) - # Update the spinner. - if use_spinner: - assert 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 ) @@ -250,7 +275,7 @@ def call_subprocess( else: raise ValueError('Invalid value: on_returncode={!r}'.format( on_returncode)) - return ''.join(all_output) + return output def runner_with_spinner_message(message): From 74369e860e5b6d1ea6fed4144cb9b506287990ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Mon, 21 Dec 2020 14:46:21 +0100 Subject: [PATCH 8/9] vcs: capture subprocess stdout only --- news/8876.bugfix.rst | 3 +++ src/pip/_internal/utils/subprocess.py | 10 +++---- src/pip/_internal/vcs/bazaar.py | 6 +++-- src/pip/_internal/vcs/git.py | 35 ++++++++++++++++++++----- src/pip/_internal/vcs/mercurial.py | 19 +++++++++++--- src/pip/_internal/vcs/subversion.py | 5 +++- src/pip/_internal/vcs/versioncontrol.py | 6 +++-- 7 files changed, 63 insertions(+), 21 deletions(-) create mode 100644 news/8876.bugfix.rst diff --git a/news/8876.bugfix.rst b/news/8876.bugfix.rst new file mode 100644 index 000000000..98250dc97 --- /dev/null +++ b/news/8876.bugfix.rst @@ -0,0 +1,3 @@ +Fixed hanging VCS subprocess calls when the VCS outputs a large amount of data +on stderr. Restored logging of VCS errors that was inadvertently removed in pip +20.2. diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index 3c79c7289..a75bc6875 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -190,9 +190,6 @@ def call_subprocess( cwd=cwd, env=env, ) - assert proc.stdin - assert proc.stdout - proc.stdin.close() except Exception as exc: if log_failed_cmd: subprocess_logger.critical( @@ -201,7 +198,10 @@ def call_subprocess( raise all_output = [] if not stdout_only: - # In this mode, stdout and stderr are in the same pip. + assert proc.stdout + assert proc.stdin + proc.stdin.close() + # In this mode, stdout and stderr are in the same pipe. while True: # The "line" value is a unicode string in Python 2. line = console_to_str(proc.stdout.readline()) @@ -224,7 +224,7 @@ def call_subprocess( output = ''.join(all_output) else: # In this mode, stdout and stderr are in different pipes. - # We must use the communicate which is the only safe way to read both. + # We must use communicate() which is the only safe way to read both. out_bytes, err_bytes = proc.communicate() # log line by line to preserve pip log indenting out = console_to_str(out_bytes) diff --git a/src/pip/_internal/vcs/bazaar.py b/src/pip/_internal/vcs/bazaar.py index efe524492..4a63d6faa 100644 --- a/src/pip/_internal/vcs/bazaar.py +++ b/src/pip/_internal/vcs/bazaar.py @@ -93,7 +93,9 @@ class Bazaar(VersionControl): @classmethod def get_remote_url(cls, location): - urls = cls.run_command(['info'], show_stdout=False, cwd=location) + urls = cls.run_command( + ['info'], show_stdout=False, stdout_only=True, cwd=location + ) for line in urls.splitlines(): line = line.strip() for x in ('checkout of branch: ', @@ -108,7 +110,7 @@ class Bazaar(VersionControl): @classmethod def get_revision(cls, location): revision = cls.run_command( - ['revno'], show_stdout=False, cwd=location, + ['revno'], show_stdout=False, stdout_only=True, cwd=location, ) return revision.splitlines()[-1] diff --git a/src/pip/_internal/vcs/git.py b/src/pip/_internal/vcs/git.py index de9c7f519..565961a06 100644 --- a/src/pip/_internal/vcs/git.py +++ b/src/pip/_internal/vcs/git.py @@ -79,7 +79,9 @@ class Git(VersionControl): def get_git_version(self): VERSION_PFX = 'git version ' - version = self.run_command(['version'], show_stdout=False) + version = self.run_command( + ['version'], show_stdout=False, stdout_only=True + ) if version.startswith(VERSION_PFX): version = version[len(VERSION_PFX):].split()[0] else: @@ -102,7 +104,11 @@ class Git(VersionControl): # and to suppress the message to stderr. args = ['symbolic-ref', '-q', 'HEAD'] output = cls.run_command( - args, extra_ok_returncodes=(1, ), show_stdout=False, cwd=location, + args, + extra_ok_returncodes=(1, ), + show_stdout=False, + stdout_only=True, + cwd=location, ) ref = output.strip() @@ -135,8 +141,13 @@ class Git(VersionControl): rev: the revision name. """ # Pass rev to pre-filter the list. - output = cls.run_command(['show-ref', rev], cwd=dest, - show_stdout=False, on_returncode='ignore') + output = cls.run_command( + ['show-ref', rev], + cwd=dest, + show_stdout=False, + stdout_only=True, + on_returncode='ignore', + ) refs = {} for line in output.strip().splitlines(): try: @@ -310,7 +321,10 @@ class Git(VersionControl): # exits with return code 1 if there are no matching lines. stdout = cls.run_command( ['config', '--get-regexp', r'remote\..*\.url'], - extra_ok_returncodes=(1, ), show_stdout=False, cwd=location, + extra_ok_returncodes=(1, ), + show_stdout=False, + stdout_only=True, + cwd=location, ) remotes = stdout.splitlines() try: @@ -346,7 +360,10 @@ class Git(VersionControl): if rev is None: rev = 'HEAD' current_rev = cls.run_command( - ['rev-parse', rev], show_stdout=False, cwd=location, + ['rev-parse', rev], + show_stdout=False, + stdout_only=True, + cwd=location, ) return current_rev.strip() @@ -359,7 +376,10 @@ class Git(VersionControl): # find the repo root git_dir = cls.run_command( ['rev-parse', '--git-dir'], - show_stdout=False, cwd=location).strip() + show_stdout=False, + stdout_only=True, + cwd=location, + ).strip() if not os.path.isabs(git_dir): git_dir = os.path.join(location, git_dir) repo_root = os.path.abspath(os.path.join(git_dir, '..')) @@ -418,6 +438,7 @@ class Git(VersionControl): ['rev-parse', '--show-toplevel'], cwd=location, show_stdout=False, + stdout_only=True, on_returncode='raise', log_failed_cmd=False, ) diff --git a/src/pip/_internal/vcs/mercurial.py b/src/pip/_internal/vcs/mercurial.py index 75e903cc8..d2d145f62 100644 --- a/src/pip/_internal/vcs/mercurial.py +++ b/src/pip/_internal/vcs/mercurial.py @@ -92,7 +92,10 @@ class Mercurial(VersionControl): def get_remote_url(cls, location): url = cls.run_command( ['showconfig', 'paths.default'], - show_stdout=False, cwd=location).strip() + show_stdout=False, + stdout_only=True, + cwd=location, + ).strip() if cls._is_local_repository(url): url = path_to_url(url) return url.strip() @@ -104,7 +107,10 @@ class Mercurial(VersionControl): """ current_revision = cls.run_command( ['parents', '--template={rev}'], - show_stdout=False, cwd=location).strip() + show_stdout=False, + stdout_only=True, + cwd=location, + ).strip() return current_revision @classmethod @@ -115,7 +121,10 @@ class Mercurial(VersionControl): """ current_rev_hash = cls.run_command( ['parents', '--template={node}'], - show_stdout=False, cwd=location).strip() + show_stdout=False, + stdout_only=True, + cwd=location, + ).strip() return current_rev_hash @classmethod @@ -131,7 +140,8 @@ class Mercurial(VersionControl): """ # find the repo root repo_root = cls.run_command( - ['root'], show_stdout=False, cwd=location).strip() + ['root'], show_stdout=False, stdout_only=True, cwd=location + ).strip() if not os.path.isabs(repo_root): repo_root = os.path.abspath(os.path.join(location, repo_root)) return find_path_to_setup_from_repo_root(location, repo_root) @@ -146,6 +156,7 @@ class Mercurial(VersionControl): ['root'], cwd=location, show_stdout=False, + stdout_only=True, on_returncode='raise', log_failed_cmd=False, ) diff --git a/src/pip/_internal/vcs/subversion.py b/src/pip/_internal/vcs/subversion.py index b84108efc..701f41db4 100644 --- a/src/pip/_internal/vcs/subversion.py +++ b/src/pip/_internal/vcs/subversion.py @@ -167,6 +167,7 @@ class Subversion(VersionControl): xml = cls.run_command( ['info', '--xml', location], show_stdout=False, + stdout_only=True, ) url = _svn_info_xml_url_re.search(xml).group(1) revs = [ @@ -218,7 +219,9 @@ class Subversion(VersionControl): # svn, version 1.12.0-SlikSvn (SlikSvn/1.12.0) # compiled May 28 2019, 13:44:56 on x86_64-microsoft-windows6.2 version_prefix = 'svn, version ' - version = self.run_command(['--version'], show_stdout=False) + version = self.run_command( + ['--version'], show_stdout=False, stdout_only=True + ) if not version.startswith(version_prefix): return () diff --git a/src/pip/_internal/vcs/versioncontrol.py b/src/pip/_internal/vcs/versioncontrol.py index 1d9cb08fe..0e807a2fb 100644 --- a/src/pip/_internal/vcs/versioncontrol.py +++ b/src/pip/_internal/vcs/versioncontrol.py @@ -676,7 +676,8 @@ class VersionControl(object): command_desc=None, # type: Optional[str] extra_environ=None, # type: Optional[Mapping[str, Any]] spinner=None, # type: Optional[SpinnerInterface] - log_failed_cmd=True # type: bool + log_failed_cmd=True, # type: bool + stdout_only=False, # type: bool ): # type: (...) -> Text """ @@ -693,7 +694,8 @@ class VersionControl(object): extra_environ=extra_environ, unset_environ=cls.unset_environ, spinner=spinner, - log_failed_cmd=log_failed_cmd) + log_failed_cmd=log_failed_cmd, + stdout_only=stdout_only) except OSError as e: # errno.ENOENT = no such file or directory # In other words, the VCS executable isn't available From 570a45ae711f7b86a99e3023207c4d263c57f908 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A9phane=20Bidoul?= Date: Tue, 22 Dec 2020 00:16:42 +0100 Subject: [PATCH 9/9] Add test for call_subprocess stdout_only --- tests/unit/test_utils_subprocess.py | 30 +++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index b0de2bf57..47c890050 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/tests/unit/test_utils_subprocess.py @@ -14,6 +14,7 @@ from pip._internal.utils.subprocess import ( format_command_args, make_command, make_subprocess_output_error, + subprocess_logger, ) @@ -154,6 +155,35 @@ def test_make_subprocess_output_error__non_ascii_line(): assert actual == expected, u'actual: {}'.format(actual) +@pytest.mark.parametrize( + ('stdout_only', 'expected'), + [ + (True, ("out\n", "out\r\n")), + (False, ("out\nerr\n", "out\r\nerr\r\n", "err\nout\n", "err\r\nout\r\n")), + ], +) +def test_call_subprocess_stdout_only(capfd, monkeypatch, stdout_only, expected): + log = [] + monkeypatch.setattr(subprocess_logger, "debug", lambda *args: log.append(args[0])) + out = call_subprocess( + [ + sys.executable, + "-c", + "import sys; " + "sys.stdout.write('out\\n'); " + "sys.stderr.write('err\\n')" + ], + stdout_only=stdout_only, + ) + assert out in expected + captured = capfd.readouterr() + assert captured.err == "" + assert ( + log == ["Running command %s", "out", "err"] + or log == ["Running command %s", "err", "out"] + ) + + class FakeSpinner(SpinnerInterface): def __init__(self):