Prevent subprocess stdout and stderr from cluttering pip's stdout.

news/1219.bugfix

+The stdout and stderr from VCS commands run by pip as subprocesses (e.g.
+``git``, ``hg``, etc.) no longer pollute pip's stdout.

src/pip/_internal/utils/logging.py

@@ -6,12 +6,13 @@ import logging
 import logging.handlers
 import os
 import sys
+from logging import Filter
 
 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.misc import ensure_dir, subprocess_logger
 
 try:
     import threading
@@ -225,7 +226,7 @@ class BetterRotatingFileHandler(logging.handlers.RotatingFileHandler):
         return logging.handlers.RotatingFileHandler._open(self)
 
 
-class MaxLevelFilter(logging.Filter):
+class MaxLevelFilter(Filter):
 
     def __init__(self, level):
         self.level = level
@@ -234,6 +235,18 @@ class MaxLevelFilter(logging.Filter):
         return record.levelno < self.level
 
 
+class ExcludeLoggerFilter(Filter):
+
+    """
+    A logging Filter that excludes records from a logger (or its children).
+    """
+
+    def filter(self, record):
+        # The base Filter class allows only records from a logger (or its
+        # children).
+        return not super(ExcludeLoggerFilter, self).filter(record)
+
+
 def setup_logging(verbosity, no_color, user_log_file):
     """Configures and sets up all of the logging
 
@@ -277,6 +290,9 @@ def setup_logging(verbosity, no_color, user_log_file):
         "stream": "pip._internal.utils.logging.ColorizedStreamHandler",
         "file": "pip._internal.utils.logging.BetterRotatingFileHandler",
     }
+    handlers = ["console", "console_errors", "console_subprocess"] + (
+        ["user_log"] if include_user_log else []
+    )
 
     logging.config.dictConfig({
         "version": 1,
@@ -286,6 +302,14 @@ def setup_logging(verbosity, no_color, user_log_file):
                 "()": "pip._internal.utils.logging.MaxLevelFilter",
                 "level": logging.WARNING,
             },
+            "restrict_to_subprocess": {
+                "()": "logging.Filter",
+                "name": subprocess_logger.name,
+            },
+            "exclude_subprocess": {
+                "()": "pip._internal.utils.logging.ExcludeLoggerFilter",
+                "name": subprocess_logger.name,
+            },
         },
         "formatters": {
             "indent": {
@@ -304,7 +328,7 @@ def setup_logging(verbosity, no_color, user_log_file):
                 "class": handler_classes["stream"],
                 "no_color": no_color,
                 "stream": log_streams["stdout"],
-                "filters": ["exclude_warnings"],
+                "filters": ["exclude_subprocess", "exclude_warnings"],
                 "formatter": "indent",
             },
             "console_errors": {
@@ -312,6 +336,17 @@ def setup_logging(verbosity, no_color, user_log_file):
                 "class": handler_classes["stream"],
                 "no_color": no_color,
                 "stream": log_streams["stderr"],
+                "filters": ["exclude_subprocess"],
+                "formatter": "indent",
+            },
+            # A handler responsible for logging to the console messages
+            # from the "subprocessor" logger.
+            "console_subprocess": {
+                "level": level,
+                "class": handler_classes["stream"],
+                "no_color": no_color,
+                "stream": log_streams["stderr"],
+                "filters": ["restrict_to_subprocess"],
                 "formatter": "indent",
             },
             "user_log": {
@@ -324,9 +359,7 @@ def setup_logging(verbosity, no_color, user_log_file):
         },
         "root": {
             "level": root_level,
-            "handlers": ["console", "console_errors"] + (
-                ["user_log"] if include_user_log else []
-            ),
+            "handlers": handlers,
         },
         "loggers": {
             "pip._vendor": {

src/pip/_internal/utils/misc.py

@@ -65,6 +65,7 @@ __all__ = ['rmtree', 'display_path', 'backup_dir',
 
 
 logger = std_logging.getLogger(__name__)
+subprocess_logger = std_logging.getLogger('pip.subprocessor')
 
 LOG_DIVIDER = '----------------------------------------'
 
@@ -671,6 +672,8 @@ def call_subprocess(
     # type: (...) -> Optional[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
@@ -680,39 +683,42 @@ def call_subprocess(
         extra_ok_returncodes = []
     if unset_environ is None:
         unset_environ = []
-    # This function's handling of subprocess output is confusing and I
-    # previously broke it terribly, so as penance I will write a long comment
-    # explaining things.
+    # Most places in pip use show_stdout=False. What this means is--
     #
-    # The obvious thing that affects output is the show_stdout=
-    # kwarg. show_stdout=True means, let the subprocess write directly to our
-    # stdout. It is almost never used
-    # inside pip (and should not be used in new code without a very good
-    # reason); as of 2016-02-22 it is only used in a few places inside the VCS
-    # wrapper code. Ideally we should get rid of it entirely, because it
-    # creates a lot of complexity here for a rarely used feature.
+    # - 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.
     #
-    # Most places in pip use show_stdout=False. What this means is:
-    # - We connect the child stdout to a pipe, which we read.
-    # - By default, we hide the output but show a spinner -- unless the
-    #   subprocess exits with an error, in which case we show the output.
-    # - If the --verbose option was passed (= loglevel is DEBUG), then we show
-    #   the output unconditionally. (But in this case we don't want to show
-    #   the output a second time if it turns out that there was an error.)
-    #
-    # stderr is always merged with stdout (even if show_stdout=True).
+    # If show_stdout=True, then the above is still done, but with DEBUG
+    # replaced by INFO.
     if show_stdout:
-        stdout = None
+        # Then log the subprocess output at INFO level.
+        log_subprocess = subprocess_logger.info
+        used_level = std_logging.INFO
     else:
-        stdout = subprocess.PIPE
+        # 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 = std_logging.DEBUG
+
+    # Whether the subprocess will be visible in the console.
+    showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level
 
-    # Only use the spinner when we're capturing stdout and we have one.
-    use_spinner = not show_stdout and spinner is not None
+    # 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)
 
-    logger.debug("Running command %s", command_desc)
+    log_subprocess("Running command %s", command_desc)
     env = os.environ.copy()
     if extra_environ:
         env.update(extra_environ)
@@ -721,29 +727,27 @@ def call_subprocess(
     try:
         proc = subprocess.Popen(
             cmd, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
-            stdout=stdout, cwd=cwd, env=env,
+            stdout=subprocess.PIPE, cwd=cwd, env=env,
         )
         proc.stdin.close()
     except Exception as exc:
-        logger.critical(
+        subprocess_logger.critical(
             "Error %s while executing command %s", exc, command_desc,
         )
         raise
     all_output = []
-    if stdout is not None:
-        while True:
-            line = console_to_str(proc.stdout.readline())
-            if not line:
-                break
-            line = line.rstrip()
-            all_output.append(line + '\n')
-            if logger.getEffectiveLevel() <= std_logging.DEBUG:
-                # Show the line immediately
-                logger.debug(line)
-            else:
-                # Update the spinner
-                if use_spinner:
-                    spinner.spin()
+    while True:
+        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:
@@ -759,18 +763,19 @@ def call_subprocess(
             spinner.finish("done")
     if proc_had_error:
         if on_returncode == 'raise':
-            if (logger.getEffectiveLevel() > std_logging.DEBUG and
-                    not show_stdout):
-                logger.info(
+            if not showing_subprocess:
+                # Then the subprocess streams haven't been logged to the
+                # console yet.
+                subprocess_logger.error(
                     'Complete output from command %s:', command_desc,
                 )
                 # The all_output value already ends in a newline.
-                logger.info(''.join(all_output) + LOG_DIVIDER)
+                subprocess_logger.error(''.join(all_output) + LOG_DIVIDER)
             raise InstallationError(
                 'Command "%s" failed with error code %s in %s'
                 % (command_desc, proc.returncode, cwd))
         elif on_returncode == 'warn':
-            logger.warning(
+            subprocess_logger.warning(
                 'Command "%s" had error code %s in %s',
                 command_desc, proc.returncode, cwd,
             )
@@ -779,9 +784,7 @@ def call_subprocess(
         else:
             raise ValueError('Invalid value: on_returncode=%s' %
                              repr(on_returncode))
-    if not show_stdout:
-        return ''.join(all_output)
-    return None
+    return ''.join(all_output)
 
 
 def _make_build_dir(build_dir):

tests/functional/test_install.py

@@ -160,7 +160,7 @@ def test_pep518_forkbombs(script, data, common_wheels, command, package):
     )
     assert '{1} is already being built: {0} from {1}'.format(
         package, path_to_url(package_source),
-    ) in result.stdout, str(result)
+    ) in result.stderr, str(result)
 
 
 @pytest.mark.network
@@ -937,8 +937,9 @@ def test_install_package_that_emits_unicode(script, data):
         'install', to_install, expect_error=True, expect_temp=True, quiet=True,
     )
     assert (
-        'FakeError: this package designed to fail on install' in result.stdout
+        'FakeError: this package designed to fail on install' in result.stderr
     )
+    assert 'UnicodeDecodeError' not in result.stderr
     assert 'UnicodeDecodeError' not in result.stdout
 
 
@@ -1119,19 +1120,19 @@ def test_install_subprocess_output_handling(script, data):
     # With --verbose we should show the output.
     # Only count examples with sys.argv[1] == egg_info, because we call
     # setup.py multiple times, which should not count as duplicate output.
-    result = script.pip(*(args + ["--verbose"]))
-    assert 1 == result.stdout.count("HELLO FROM CHATTYMODULE egg_info")
+    result = script.pip(*(args + ["--verbose"]), expect_stderr=True)
+    assert 1 == result.stderr.count("HELLO FROM CHATTYMODULE egg_info")
     script.pip("uninstall", "-y", "chattymodule")
 
     # If the install fails, then we *should* show the output... but only once,
     # even if --verbose is given.
     result = script.pip(*(args + ["--global-option=--fail"]),
                         expect_error=True)
-    assert 1 == result.stdout.count("I DIE, I DIE")
+    assert 1 == result.stderr.count("I DIE, I DIE")
 
     result = script.pip(*(args + ["--global-option=--fail", "--verbose"]),
                         expect_error=True)
-    assert 1 == result.stdout.count("I DIE, I DIE")
+    assert 1 == result.stderr.count("I DIE, I DIE")
 
 
 def test_install_log(script, data, tmpdir):

tests/functional/test_wheel.py

@@ -118,7 +118,7 @@ def test_pip_wheel_fail(script, data):
         wheel_file_path,
         result.files_created,
     )
-    assert "FakeError" in result.stdout, result.stdout
+    assert "FakeError" in result.stderr, result.stderr
     assert "Failed to build wheelbroken" in result.stdout, result.stdout
     assert result.returncode != 0
 

tests/unit/test_utils.py

@@ -6,7 +6,6 @@ util tests
 """
 import codecs
 import itertools
-import logging
 import os
 import shutil
 import stat
@@ -15,6 +14,7 @@ import tempfile
 import time
 import warnings
 from io import BytesIO
+from logging import DEBUG, ERROR, INFO, WARNING
 
 import pytest
 from mock import Mock, patch
@@ -781,30 +781,25 @@ class TestCallSubprocess(object):
         :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 3-tuple (expected_proc, expected_out,
-            expected_records), where
+        :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_out` is the expected stdout captured from the
-              subprocess call, as a list of lines; and
-            3) `expected_records` is the expected value of
+            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_out, expected_records = expected
+        expected_proc, expected_records = expected
 
         if expected_proc is None:
-            assert result is expected_proc
+            assert result is None
         else:
             assert result.splitlines() == expected_proc
 
+        # Confirm that stdout and stderr haven't been written to.
         captured = capfd.readouterr()
-        stdout, stderr = captured.out, captured.err
-
-        assert stdout.splitlines() == expected_out
-        assert stderr == ''
+        assert (captured.out, captured.err) == ('', '')
 
         records = caplog.record_tuples
         if len(records) != len(expected_records):
@@ -837,31 +832,31 @@ class TestCallSubprocess(object):
         """
         Test DEBUG logging (and without passing show_stdout=True).
         """
-        log_level = logging.DEBUG
+        log_level = DEBUG
         args, spinner = self.prepare_call(caplog, log_level)
         result = call_subprocess(args, spinner=spinner)
 
-        expected = (['Hello', 'world'], [], [
-            ('pip._internal.utils.misc', 10, 'Running command '),
-            ('pip._internal.utils.misc', 10, 'Hello'),
-            ('pip._internal.utils.misc', 10, 'world'),
+        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, 'done'),
+            expected_spinner=(0, None),
         )
 
     def test_info_logging(self, capfd, caplog):
         """
         Test INFO logging (and without passing show_stdout=True).
         """
-        log_level = logging.INFO
+        log_level = INFO
         args, spinner = self.prepare_call(caplog, log_level)
         result = call_subprocess(args, spinner=spinner)
 
-        expected = (['Hello', 'world'], [], [])
+        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(
@@ -874,7 +869,7 @@ class TestCallSubprocess(object):
         Test INFO logging of a subprocess with an error (and without passing
         show_stdout=True).
         """
-        log_level = logging.INFO
+        log_level = INFO
         command = 'print("Hello"); print("world"); exit("fail")'
         args, spinner = self.prepare_call(caplog, log_level, command=command)
 
@@ -882,10 +877,10 @@ class TestCallSubprocess(object):
             call_subprocess(args, spinner=spinner)
         result = None
 
-        expected = (None, [], [
-            ('pip._internal.utils.misc', 20, 'Complete output from command '),
+        expected = (None, [
+            ('pip.subprocessor', ERROR, 'Complete output from command '),
             # The "failed" portion is later on in this "Hello" string.
-            ('pip._internal.utils.misc', 20, 'Hello'),
+            ('pip.subprocessor', ERROR, 'Hello'),
         ])
         # The spinner should spin three times in this case since the
         # subprocess output isn't being written to the console.
@@ -915,11 +910,15 @@ class TestCallSubprocess(object):
         """
         Test INFO logging with show_stdout=True.
         """
-        log_level = logging.INFO
+        log_level = INFO
         args, spinner = self.prepare_call(caplog, log_level)
         result = call_subprocess(args, spinner=spinner, show_stdout=True)
 
-        expected = (None, ['Hello', 'world'], [])
+        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(
@@ -931,17 +930,23 @@ class TestCallSubprocess(object):
         'exit_status', 'show_stdout', 'extra_ok_returncodes', 'log_level',
         'expected'),
         [
-            (0, False, None, logging.INFO, (None, 'done', 2)),
-            # Test some cases that should result in show_spinner false.
-            (0, False, None, logging.DEBUG, (None, 'done', 0)),
+            # 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, logging.DEBUG, (None, None, 0)),
-            (0, True, None, logging.INFO, (None, None, 0)),
-            (0, True, None, logging.WARNING, (None, None, 0)),
+            (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, logging.INFO, (InstallationError, 'error', 2)),
+            (3, False, None, INFO, (InstallationError, 'error', 2)),
             # Test a non-zero exit status also in extra_ok_returncodes.
-            (3, False, (3, ), logging.INFO, (None, 'done', 2)),
+            (3, False, (3, ), INFO, (None, 'done', 2)),
     ])
     def test_spinner_finish(
         self, exit_status, show_stdout, extra_ok_returncodes, log_level,