-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`

Author: minrk

news/9447.feature.rst

@@ -0,0 +1 @@
+Require ``-vv`` for full debug-level output, ``-v`` now only enables showing subprocess output, e.g. of ``setup.py install``.

src/pip/_internal/commands/cache.py

@@ -6,6 +6,7 @@
 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
 from pip._internal.utils.typing import MYPY_CHECK_RUNNING
 
 if MYPY_CHECK_RUNNING:
@@ -188,7 +189,7 @@ def remove_cache_items(self, options, args):
 
         for filename in files:
             os.unlink(filename)
-            logger.debug('Removed %s', filename)
+            logger.log(VERBOSE, 'Removed %s', filename)
         logger.info('Files removed: %s', len(files))
 
     def purge_cache(self, options, args):

src/pip/_internal/commands/install.py

@@ -21,6 +21,7 @@
 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_installed_version,
@@ -236,7 +237,7 @@ def run(self, options, args):
 
         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

@@ -11,7 +11,7 @@
 from pip._internal.exceptions import UninstallationError
 from pip._internal.locations import bin_py, 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,
@@ -398,7 +398,7 @@ def remove(self, auto_confirm=False, verbose=False):
 
                 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()
@@ -613,7 +613,7 @@ def add(self, entry):
 
     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):
@@ -634,7 +634,7 @@ def remove(self):
             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

@@ -31,6 +31,11 @@
 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.
@@ -245,19 +250,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 os
 import shlex
 import subprocess
+from functools import partial
 
 from pip._internal.cli.spinners import SpinnerInterface, open_spinner
 from pip._internal.exceptions import InstallationSubprocessError
 from pip._internal.utils.compat import console_to_str, str_to_display
-from pip._internal.utils.logging import subprocess_logger
+from pip._internal.utils.logging import VERBOSE, subprocess_logger
 from pip._internal.utils.misc import HiddenText, path_to_display
 from pip._internal.utils.typing import MYPY_CHECK_RUNNING
 
@@ -158,8 +159,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 @@ def test_raise_broken_stdout__debug_logging(self, capsys):
         """
         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 @@
 
 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,
@@ -163,7 +164,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,
@@ -269,9 +274,9 @@ def test_debug_logging(self, capfd, caplog):
         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.