Create a custom call_subprocess for vcs commands avoiding merging of stdout and stderr, and introduces a new SubprocessError exception

[deveshks]

Fixes and Closes #7968 , Closes #7841 , Closes #7711 and Closes #7545

It's not always guaranteed that the version string in the output of svn --version is present in the first line, which is currently what the code assumes, for e.g.

$ svn --version 
Warning: Failed to set locale category LC_NUMERIC to en_IN.
Warning: Failed to set locale category LC_TIME to en_IN.
Warning: Failed to set locale category LC_COLLATE to en_IN.
Warning: Failed to set locale category LC_MONETARY to en_IN.
Warning: Failed to set locale category LC_MESSAGES to en_IN.
svn, version 1.13.0 (r1867053)
   compiled Feb 19 2020, 02:08:03 on x86_64-apple-darwin19.3.0

Copyright (C) 2019 The Apache Software Foundation.
This software consists of contributions made by many people;
see the NOTICE file for more information.
Subversion is open source software, see http://subversion.apache.org/

The following repository access (RA) modules are available:

* ra_svn : Module for accessing a repository using the svn network protocol.
  - with Cyrus SASL authentication
  - handles 'svn' scheme
* ra_local : Module for accessing a repository on local disk.
  - handles 'file' scheme
* ra_serf : Module for accessing a repository via WebDAV protocol using serf.
  - using serf 1.3.9 (compiled with 1.3.9)
  - handles 'http' scheme
  - handles 'https' scheme

The following authentication credential caches are available:

* Mac OS X Keychain

This happens because we were using utils.subproces.call_subprocess in vcs, which merges stdout and stderr.

This change creates a custom call_subprocess for vcs commands to avoid merging stdout and stderr, and introduces a new SubprocessError exception to replace the older InstallationError being raised before.

[uranusjr]

Could you try whether the version is the first line of stdout though? If it is, the proper fix would be to re-implement run_command to not merge stdout and stderr. I believe there is an issue open for that.

[deveshks]

Hi @uranusjr

If I understand correctly, you want me to try out the following.

def call_vcs_version(self):
    version_prefix = 'svn, version '
    version = self.run_command(['--version'], show_stdout=True)
    print(version)

I tried it and I got the following output

Warning: Failed to set locale category LC_NUMERIC to en_IN.
Warning: Failed to set locale category LC_TIME to en_IN.
Warning: Failed to set locale category LC_COLLATE to en_IN.
Warning: Failed to set locale category LC_MONETARY to en_IN.
Warning: Failed to set locale category LC_MESSAGES to en_IN.
svn, version 1.13.0 (r1867053)
   compiled Feb 19 2020, 02:08:03 on x86_64-apple-darwin19.3.0

.....

As you can see, even with show_stdout=True, version is not the first line of output. Let me know if that answers your question, or you wanted me to try out something else.

[McSinyx]

In call_subprocess which called by run_command,

# 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.
# [...]
#
# If show_stdout=True, then the above is still done, but with DEBUG
# replaced by INFO.
try:
    proc = subprocess.Popen(
        ...
        stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
        stdout=subprocess.PIPE, cwd=cwd, env=env,

I'm not sure what's the cost of changing this hard-coded behavior though. BTW if we still going in the direction of just fixing svn version parser, why not using regex, e.g.

def call_vcs_version(self):
    match = re.search('^svn, version (\d+(?:\.\d+)*)\s', a)
    if match is None:
        return ()
    return tuple(map(int, match.group(1).split('.')))

[deveshks]

Thanks @McSinyx for the suggestion on using regex.

I can update my code to use regex instead of the current logic, once @uranusjr confirms it's okay to do so and we don't need to re-implement run_command to not merge stdout and stderr.

[uranusjr]

My suggestion would be to re-implement run_command with subprocess directly, instead of chaing call_subprocess. Most of the logic in there is not useful at all for VCS commands anyway, and it has been pointed out in the past that call_subprocess is a wrong abstraction here, since it raises InstallationError which does not make sense in VCS classes.

[deveshks]

Hi @uranusjr

So if I understand correctly, we want to use subprocess.Popen directly here instead of using call_subprocess.

Okay I will investigate it and make necessary changes, while making sure the vcs based tests still pass.

BTW I see that the parameters of call_subprocess which are being used in existing calls to it in pip._internal.vc modules are cmd, show_stdout, cwd, on_returncode, extra_ok_returncodes and log_failed_cmd

I know that we have to use cmd and cwd, and we can ignore show_stdout, but what about the remaining three parameters, on_returncode, extra_ok_returncodes and log_failed_cmd ? Which of them do we need in VCS, and which one can be ignored? I will build the logic around using subprocess.Popen accordingly.

[deveshks]

Hi @uranusjr

So as per your suggestion, I have made a copy of run_command just for the vcs submodule, where I got rid of command_desc, unset_environ and spinner, since they were not used in vcs module, and show_stdout, which was always set to False. I also introduced a new SubProcessError to take place of InstallationError in this copy.

However apart from cmd and cmd, I have still kept on_returncode, extra_ok_returncodes and log_failed_cmd since they are being used in the vcs module for run_command, and extra_environ, which is being used in tests.functional.test_vcs_git. I am not sure if we want to get rid of some of them, or keep them as in, so any pointers on the same are welcome.

[deveshks]

Hi @uranusjr ,

Would appreciate your thoughts on the changes in the PR, especially the comment above #7969 (comment), so that it can be moved forward towards more implementation reviews, or if there are better ways to achieve what I am trying to do here.

[deveshks]

I have gone ahead and dropped on_returncode from the call_subprocess, and I am catching the exceptions at the call sites now.

Please review the changes and let me know if anything else is needed, especially what do we want to do with extra_ok_returncodes, log_failed_cmd and extra_environ parameter (which is only being used here and here.

[uranusjr]

It just now occurs to me, we need to add something to catch the SubProcessError bubbled from within the VCS class. The previous implementation uses InstallationError, which is bubbled all the way to BaseCommand._main() and gets turned into an error message. So we’ll need to do something similar to what you did for HTTPError in another PR.

[deveshks]

It just now occurs to me, we need to add something to catch the SubProcessError bubbled from within the VCS class. The previous implementation uses InstallationError, which is bubbled all the way to BaseCommand._main() and gets turned into an error message. So we’ll need to do something similar to what you did for HTTPError in another PR.

If my memory serves me right, I assume you are referring to the PR #8133 in the above comment which is currently approved and done by @gutsytechster ? (I see that in the PR, a new NetworkConnectionError is raised, and is caught in base_command._main, I will look into it and implement it in this PR)

[deveshks]

.The previous implementation uses InstallationError, which is bubbled all the way to BaseCommand._main() and gets turned into an error message.

Added 53cc0d7 for this by catching SubProcessError explicitly in base_command._main, now we see the following on running a bad pip command involving git.

Please let me know if this was the change you mentioned to add, or did I miss something.

$ pip install git+ssh://[email protected]/MYORGNAME/MYREPO.git@mycommit -v
Non-user install because user site-packages disabled
Created temporary directory: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-ephem-wheel-cache-710ghg3e
Created temporary directory: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-tracker-g6_l66tc
Initialized build tracking at /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-tracker-g6_l66tc
Created build tracker: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-tracker-g6_l66tc
Entered build tracker: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-tracker-g6_l66tc
Created temporary directory: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-install-428tn2_c
Collecting git+ssh://****@github.com/MYORGNAME/MYREPO.git@mycommit
  Created temporary directory: /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-build-cah_0gm7
  Cloning ssh://****@github.com/MYORGNAME/MYREPO.git (to revision mycommit) to /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-build-cah_0gm7
ERROR: Command errored out with exit status 128: git clone -q 'ssh://****@github.com/MYORGNAME/MYREPO.git' /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-build-cah_0gm7 Check the logs for full command output.
Exception information:
Traceback (most recent call last):
  File "/Users/devesh/pip/src/pip/_internal/cli/base_command.py", line 189, in _main
    status = self.run(options, args)
  File "/Users/devesh/pip/src/pip/_internal/cli/req_command.py", line 184, in wrapper
    return func(self, options, args)
  File "/Users/devesh/pip/src/pip/_internal/commands/install.py", line 329, in run
    requirement_set = resolver.resolve(
  File "/Users/devesh/pip/src/pip/_internal/resolution/legacy/resolver.py", line 180, in resolve
    discovered_reqs.extend(self._resolve_one(requirement_set, req))
  File "/Users/devesh/pip/src/pip/_internal/resolution/legacy/resolver.py", line 385, in _resolve_one
    abstract_dist = self._get_abstract_dist_for(req_to_install)
  File "/Users/devesh/pip/src/pip/_internal/resolution/legacy/resolver.py", line 337, in _get_abstract_dist_for
    abstract_dist = self.preparer.prepare_linked_requirement(req)
  File "/Users/devesh/pip/src/pip/_internal/operations/prepare.py", line 467, in prepare_linked_requirement
    local_file = unpack_url(
  File "/Users/devesh/pip/src/pip/_internal/operations/prepare.py", line 239, in unpack_url
    unpack_vcs_link(link, location)
  File "/Users/devesh/pip/src/pip/_internal/operations/prepare.py", line 99, in unpack_vcs_link
    vcs_backend.unpack(location, url=hide_url(link.url))
  File "/Users/devesh/pip/src/pip/_internal/vcs/versioncontrol.py", line 733, in unpack
    self.obtain(location, url=url)
  File "/Users/devesh/pip/src/pip/_internal/vcs/versioncontrol.py", line 641, in obtain
    self.fetch_new(dest, url, rev_options)
  File "/Users/devesh/pip/src/pip/_internal/vcs/git.py", line 230, in fetch_new
    self.run_command(make_command('clone', '-q', url, dest))
  File "/Users/devesh/pip/src/pip/_internal/vcs/versioncontrol.py", line 771, in run_command
    return call_subprocess(cmd, cwd,
  File "/Users/devesh/pip/src/pip/_internal/vcs/versioncontrol.py", line 166, in call_subprocess
    raise SubProcessError(exc_msg)
pip._internal.exceptions.SubProcessError: Command errored out with exit status 128: git clone -q 'ssh://****@github.com/MYORGNAME/MYREPO.git' /private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-build-cah_0gm7 Check the logs for full command output.
Removed build tracker: '/private/var/folders/xg/blp845_s0xn093dyrtgy936h0000gp/T/pip-req-tracker-g6_l66tc'

[uranusjr]

The output looks right to me (yay)

[deveshks]

The output looks right to me (yay)

Thanks, Are there any other changes needed here? If no, could I please get the PR approved.

(Would also appreciate your thoughts on how to better reword the news entry, include the type, and if this even needs a news entry).

[uranusjr]

Assuming CI passes

[deveshks]

Assuming CI passes

Thanks for the approval 😊 , and the CI passed too.

[pradyunsg]

This PR's title, and the changelog should probably be updated, to reflect everything that's being changed here.

The code change LGTM.

[deveshks]

I think this should also fix:

1. Exposed credentials #7841 since the culprit log_subprocess("Running command %s", command_desc) is not present in the new call_subprocess anymore

2. Refactor call_subprocess() to not raise InstallationError #7711 since we are raising SubProcessError now instead of InstallationError

3. VCS invocation merges stdout and stderr, resulting in output parsing error #7545 since we have separate pipes for stdout and stderr now for vcs subprocess calls

If yes, I will go ahead and add these to the PR description, so that they will auto close once this is merged. Please do let me know if any of those PR are actually not being fixed here.

I will also add a comment to each one of them mentioning this PR and how it was fixed once this is merged for completeness.

[uranusjr]

@deveshks Sounds right to me.

[pradyunsg]

I'm gonna trust @uranusjr's judgement here, and merge this in. :)