-v shows subprocess output

adds VERBOSE custom log level between DEBUG and INFO

used when `-v` is given. Now require -vv to enable full debug output.

Messages can be logged with VERBOSE level to promote them to `-v` output instead of `-vv`

news/9450.feature.rst

@@ -0,0 +1,2 @@
+Require ``-vv`` for full debug-level output, ``-v`` now enables an intermediate level of verbosity,
+e.g. showing subprocess output of ``setup.py install`` but not all dependency resolution debug output.

src/pip/_internal/commands/cache.py

@@ -8,6 +8,7 @@ import pip._internal.utils.filesystem as filesystem
 from pip._internal.cli.base_command import Command
 from pip._internal.cli.status_codes import ERROR, SUCCESS
 from pip._internal.exceptions import CommandError, PipError
+from pip._internal.utils.logging import VERBOSE
 
 logger = logging.getLogger(__name__)
 
@@ -184,8 +185,8 @@ class CacheCommand(Command):
 
         for filename in files:
             os.unlink(filename)
-            logger.debug('Removed %s', filename)
-        logger.info('Files removed: %s', len(files))
+            logger.log(VERBOSE, "Removed %s", filename)
+        logger.info("Files removed: %s", len(files))
 
     def purge_cache(self, options, args):
         # type: (Values, List[Any]) -> None

src/pip/_internal/commands/install.py

@@ -28,6 +28,7 @@ from pip._internal.req.req_install import InstallRequirement
 from pip._internal.req.req_tracker import get_requirement_tracker
 from pip._internal.utils.distutils_args import parse_distutils_args
 from pip._internal.utils.filesystem import test_writable_dir
+from pip._internal.utils.logging import VERBOSE
 from pip._internal.utils.misc import (
     ensure_dir,
     get_pip_version,
@@ -235,7 +236,7 @@ class InstallCommand(RequirementCommand):
 
         install_options = options.install_options or []
 
-        logger.debug("Using %s", get_pip_version())
+        logger.log(VERBOSE, "Using %s", get_pip_version())
         options.use_user_site = decide_user_install(
             options.use_user_site,
             prefix_path=options.prefix_path,

src/pip/_internal/req/req_uninstall.py

@@ -13,7 +13,7 @@ from pip._vendor.pkg_resources import Distribution
 from pip._internal.exceptions import UninstallationError
 from pip._internal.locations import get_bin_prefix, get_bin_user
 from pip._internal.utils.compat import WINDOWS
-from pip._internal.utils.logging import indent_log
+from pip._internal.utils.logging import VERBOSE, indent_log
 from pip._internal.utils.misc import (
     ask,
     dist_in_usersite,
@@ -384,7 +384,7 @@ class UninstallPathSet:
 
                 for path in sorted(compact(for_rename)):
                     moved.stash(path)
-                    logger.debug('Removing file or directory %s', path)
+                    logger.log(VERBOSE, 'Removing file or directory %s', path)
 
                 for pth in self.pth.values():
                     pth.remove()
@@ -599,7 +599,7 @@ class UninstallPthEntries:
 
     def remove(self):
         # type: () -> None
-        logger.debug('Removing pth entries from %s:', self.file)
+        logger.log(VERBOSE, 'Removing pth entries from %s:', self.file)
 
         # If the file doesn't exist, log a warning and return
         if not os.path.isfile(self.file):
@@ -620,7 +620,7 @@ class UninstallPthEntries:
             lines[-1] = lines[-1] + endline.encode("utf-8")
         for entry in self.entries:
             try:
-                logger.debug('Removing entry: %s', entry)
+                logger.log(VERBOSE, 'Removing entry: %s', entry)
                 lines.remove((entry + endline).encode("utf-8"))
             except ValueError:
                 pass

src/pip/_internal/utils/logging.py

@@ -29,6 +29,11 @@ _log_state = threading.local()
 subprocess_logger = getLogger("pip.subprocessor")
 
 
+# custom log level for `--verbose` output
+# between DEBUG and INFO
+VERBOSE = 15
+
+
 class BrokenStdoutLoggingError(Exception):
     """
     Raised if BrokenPipeError occurs for the stdout stream while logging.
@@ -271,19 +276,22 @@ def setup_logging(verbosity, no_color, user_log_file):
     Returns the requested logging level, as its integer value.
     """
 
+    logging.addLevelName(VERBOSE, "VERBOSE")
     # Determine the level to be logging at.
-    if verbosity >= 1:
-        level = "DEBUG"
+    if verbosity >= 2:
+        level_number = logging.DEBUG
+    elif verbosity == 1:
+        level_number = VERBOSE
     elif verbosity == -1:
-        level = "WARNING"
+        level_number = logging.WARNING
     elif verbosity == -2:
-        level = "ERROR"
+        level_number = logging.ERROR
     elif verbosity <= -3:
-        level = "CRITICAL"
+        level_number = logging.CRITICAL
     else:
-        level = "INFO"
+        level_number = logging.INFO
 
-    level_number = getattr(logging, level)
+    level = logging.getLevelName(level_number)
 
     # The "root" logger should match the "console" level *unless* we also need
     # to log to a user log file.

src/pip/_internal/utils/subprocess.py

@@ -2,11 +2,12 @@ import logging
 import os
 import shlex
 import subprocess
+from functools import partial
 from typing import Any, Callable, Iterable, List, Mapping, Optional, Union
 
 from pip._internal.cli.spinners import SpinnerInterface, open_spinner
 from pip._internal.exceptions import InstallationSubprocessError
-from pip._internal.utils.logging import subprocess_logger
+from pip._internal.utils.logging import VERBOSE, subprocess_logger
 from pip._internal.utils.misc import HiddenText
 
 CommandArgs = List[Union[str, HiddenText]]
@@ -146,8 +147,8 @@ def call_subprocess(
     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
+        log_subprocess = partial(subprocess_logger.log, VERBOSE)
+        used_level = VERBOSE
 
     # Whether the subprocess will be visible in the console.
     showing_subprocess = subprocess_logger.getEffectiveLevel() <= used_level

tests/functional/test_broken_stdout.py

@@ -65,7 +65,7 @@ def test_broken_stdout_pipe__verbose(deprecated_python):
     Test a broken pipe to stdout with verbose logging enabled.
     """
     stderr, returncode = setup_broken_stdout_test(
-        ['pip', '-v', 'list'], deprecated_python=deprecated_python,
+        ['pip', '-vv', 'list'], deprecated_python=deprecated_python,
     )
 
     # Check that a traceback occurs and that it occurs at most once.

tests/functional/test_new_resolver_hashes.py

@@ -76,7 +76,7 @@ def test_new_resolver_hash_intersect(script, requirements_template, message):
         "--no-deps",
         "--no-index",
         "--find-links", find_links.index_html,
-        "--verbose",
+        "-vv",
         "--requirement", requirements_txt,
     )
 
@@ -108,7 +108,7 @@ def test_new_resolver_hash_intersect_from_constraint(script):
         "--no-deps",
         "--no-index",
         "--find-links", find_links.index_html,
-        "--verbose",
+        "-vv",
         "--constraint", constraints_txt,
         "--requirement", requirements_txt,
     )

tests/unit/test_base_command.py

@@ -80,7 +80,7 @@ class TestCommand:
         """
         Test raising BrokenStdoutLoggingError with debug logging enabled.
         """
-        stderr = self.call_main(capsys, ['-v'])
+        stderr = self.call_main(capsys, ['-vv'])
 
         assert 'ERROR: Pipe to stdout was broken' in stderr
         assert 'Traceback (most recent call last):' in stderr

tests/unit/test_utils_subprocess.py

@@ -7,6 +7,7 @@ import pytest
 
 from pip._internal.cli.spinners import SpinnerInterface
 from pip._internal.exceptions import InstallationSubprocessError
+from pip._internal.utils.logging import VERBOSE
 from pip._internal.utils.misc import hide_value
 from pip._internal.utils.subprocess import (
     call_subprocess,
@@ -127,7 +128,11 @@ def test_make_subprocess_output_error__non_ascii_line():
 )
 def test_call_subprocess_stdout_only(capfd, monkeypatch, stdout_only, expected):
     log = []
-    monkeypatch.setattr(subprocess_logger, "debug", lambda *args: log.append(args[0]))
+    monkeypatch.setattr(
+        subprocess_logger,
+        "log",
+        lambda level, *args: log.append(args[0]),
+    )
     out = call_subprocess(
         [
             sys.executable,
@@ -233,9 +238,9 @@ class TestCallSubprocess:
         result = call_subprocess(args, spinner=spinner)
 
         expected = (['Hello', 'world'], [
-            ('pip.subprocessor', DEBUG, 'Running command '),
-            ('pip.subprocessor', DEBUG, 'Hello'),
-            ('pip.subprocessor', DEBUG, 'world'),
+            ('pip.subprocessor', VERBOSE, 'Running command '),
+            ('pip.subprocessor', VERBOSE, 'Hello'),
+            ('pip.subprocessor', VERBOSE, 'world'),
         ])
         # The spinner shouldn't spin in this case since the subprocess
         # output is already being logged to the console.