Merge pull request pypa#3505 from njsmith/fix-verbose-subprocess-output

Fix display of subprocess output when --verbose is given

CHANGES.txt

@@ -6,6 +6,12 @@
   entry_point.txt file to allow entry point names with colons (:pull:`3434`)
 
 
+**8.0.3 (unreleased)**
+
+* Fix bug introduced in 8.0.0 where subcommand output was not shown,
+  even when the user specified ``-v`` / ``--verbose``.
+
+
 **8.0.2 (2016-01-21)**
 
 * Stop attempting to trust the system CA trust store because it's extremely

pip/utils/__init__.py

@@ -635,6 +635,31 @@ def call_subprocess(cmd, show_stdout=True, cwd=None,
                     on_returncode='raise',
                     command_level=std_logging.DEBUG, command_desc=None,
                     extra_environ=None, spinner=None):
+    # 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.
+    #
+    # The obvious thing that affects output is the show_stdout=
+    # kwarg. show_stdout=True means, let the subprocess write directly to our
+    # stdout. Even though it is nominally the default, 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.
+    #
+    # Most places in pip set 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:
+        stdout = None
+    else:
+        stdout = subprocess.PIPE
     if command_desc is None:
         cmd_parts = []
         for part in cmd:
@@ -648,24 +673,28 @@ def call_subprocess(cmd, show_stdout=True, cwd=None,
         env.update(extra_environ)
     try:
         proc = subprocess.Popen(
-            cmd, stderr=subprocess.STDOUT, stdin=None, stdout=subprocess.PIPE,
+            cmd, stderr=subprocess.STDOUT, stdin=None, stdout=stdout,
             cwd=cwd, env=env)
     except Exception as exc:
         logger.critical(
             "Error %s while executing command %s", exc, command_desc,
         )
         raise
-    all_output = []
-    while True:
-        line = console_to_str(proc.stdout.readline())
-        if not line:
-            break
-        line = line.rstrip()
-        all_output.append(line + '\n')
-        if show_stdout:
-            logger.debug(line)
-        if spinner is not None:
-            spinner.spin()
+    if stdout is not None:
+        all_output = []
+        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 spinner is not None:
+                    spinner.spin()
     proc.wait()
     if spinner is not None:
         if proc.returncode:
@@ -674,7 +703,7 @@ def call_subprocess(cmd, show_stdout=True, cwd=None,
             spinner.finish("done")
     if proc.returncode:
         if on_returncode == 'raise':
-            if all_output:
+            if logger.getEffectiveLevel() > std_logging.DEBUG:
                 logger.info(
                     'Complete output from command %s:', command_desc,
                 )

tests/data/src/chattymodule/chattymodule.py

@@ -0,0 +1,3 @@
+def main():
+    """Entry point for the application script"""
+    print("Call your main application code here")

tests/data/src/chattymodule/setup.cfg

@@ -0,0 +1,5 @@
+[bdist_wheel]
+# This flag says that the code is written to work on both Python 2 and Python
+# 3. If at all possible, it is good practice to do this. If you cannot, you
+# will need to generate wheels for each Python version that you support.
+universal=1

tests/data/src/chattymodule/setup.py

@@ -0,0 +1,19 @@
+# A chatty setup.py for testing pip subprocess output handling
+
+from setuptools import setup
+import os
+import sys
+
+print("HELLO FROM CHATTYMODULE %s" % (sys.argv[1],))
+print(os.environ)
+print(sys.argv)
+if "--fail" in sys.argv:
+    print("I DIE, I DIE")
+    sys.exit(1)
+
+setup(
+    name="chattymodule",
+    version='0.0.1',
+    description="A sample Python project with a single module",
+    py_modules=['chattymodule'],
+)

tests/functional/test_install.py

@@ -820,6 +820,32 @@ def test_install_upgrade_editable_depending_on_other_editable(script):
     assert "pkgb" in result.stdout
 
 
+def test_install_subprocess_output_handling(script, data):
+    args = ['install', data.src.join('chattymodule')]
+
+    # Regular install should not show output from the chatty setup.py
+    result = script.pip(*args)
+    assert 0 == result.stdout.count("HELLO FROM CHATTYMODULE")
+    script.pip("uninstall", "-y", "chattymodule")
+
+    # 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")
+    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")
+
+    result = script.pip(*(args + ["--global-option=--fail", "--verbose"]),
+                        expect_error=True)
+    assert 1 == result.stdout.count("I DIE, I DIE")
+
+
 def test_install_topological_sort(script, data):
     args = ['install', 'TopoRequires4', '-f', data.packages]
     res = str(script.pip(*args, expect_error=False))