Merge pull request #9450 from minrk/custom-log-level

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/__init__.py

@@ -1,6 +1,11 @@
 from typing import List, Optional
 
 import pip._internal.utils.inject_securetransport  # noqa
+from pip._internal.utils import _log
+
+# init_logging() must be called before any call to logging.getLogger()
+# which happens at import of most modules.
+_log.init_logging()
 
 
 def main(args: (Optional[List[str]]) = None) -> int:

src/pip/_internal/commands/cache.py

@@ -1,4 +1,3 @@
-import logging
 import os
 import textwrap
 from optparse import Values
@@ -8,8 +7,9 @@ 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 getLogger
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 class CacheCommand(Command):
@@ -184,8 +184,8 @@ class CacheCommand(Command):
 
         for filename in files:
             os.unlink(filename)
-            logger.debug('Removed %s', filename)
-        logger.info('Files removed: %s', len(files))
+            logger.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

@@ -1,5 +1,4 @@
 import errno
-import logging
 import operator
 import os
 import shutil
@@ -28,6 +27,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 getLogger
 from pip._internal.utils.misc import (
     ensure_dir,
     get_pip_version,
@@ -45,7 +45,7 @@ from pip._internal.wheel_builder import (
     should_build_for_install_command,
 )
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 def get_check_binary_allowed(format_control):
@@ -238,7 +238,7 @@ class InstallCommand(RequirementCommand):
 
         install_options = options.install_options or []
 
-        logger.debug("Using %s", get_pip_version())
+        logger.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/network/auth.py

@@ -4,7 +4,6 @@ Contains interface (MultiDomainBasicAuth) and associated glue code for
 providing credentials in the context of network requests.
 """
 
-import logging
 import urllib.parse
 from typing import Any, Dict, List, Optional, Tuple
 
@@ -12,6 +11,7 @@ from pip._vendor.requests.auth import AuthBase, HTTPBasicAuth
 from pip._vendor.requests.models import Request, Response
 from pip._vendor.requests.utils import get_netrc_auth
 
+from pip._internal.utils.logging import getLogger
 from pip._internal.utils.misc import (
     ask,
     ask_input,
@@ -21,7 +21,7 @@ from pip._internal.utils.misc import (
 )
 from pip._internal.vcs.versioncontrol import AuthInfo
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 Credentials = Tuple[str, str, str]
 

src/pip/_internal/req/req_uninstall.py

@@ -1,6 +1,5 @@
 import csv
 import functools
-import logging
 import os
 import sys
 import sysconfig
@@ -13,7 +12,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 getLogger, indent_log
 from pip._internal.utils.misc import (
     ask,
     dist_in_usersite,
@@ -26,7 +25,7 @@ from pip._internal.utils.misc import (
 )
 from pip._internal.utils.temp_dir import AdjacentTempDirectory, TempDirectory
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 def _script_names(dist, script_name, is_gui):
@@ -403,7 +402,7 @@ class UninstallPathSet:
 
                 for path in sorted(compact(for_rename)):
                     moved.stash(path)
-                    logger.debug('Removing file or directory %s', path)
+                    logger.verbose('Removing file or directory %s', path)
 
                 for pth in self.pth.values():
                     pth.remove()
@@ -618,7 +617,7 @@ class UninstallPthEntries:
 
     def remove(self):
         # type: () -> None
-        logger.debug('Removing pth entries from %s:', self.file)
+        logger.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):
@@ -639,7 +638,7 @@ class UninstallPthEntries:
             lines[-1] = lines[-1] + endline.encode("utf-8")
         for entry in self.entries:
             try:
-                logger.debug('Removing entry: %s', entry)
+                logger.verbose('Removing entry: %s', entry)
                 lines.remove((entry + endline).encode("utf-8"))
             except ValueError:
                 pass

src/pip/_internal/utils/_log.py

@@ -0,0 +1,38 @@
+"""Customize logging
+
+Defines custom logger class for the `logger.verbose(...)` method.
+
+init_logging() must be called before any other modules that call logging.getLogger.
+"""
+
+import logging
+from typing import Any, cast
+
+# custom log level for `--verbose` output
+# between DEBUG and INFO
+VERBOSE = 15
+
+
+class VerboseLogger(logging.Logger):
+    """Custom Logger, defining a verbose log-level
+
+    VERBOSE is between INFO and DEBUG.
+    """
+
+    def verbose(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        return self.log(VERBOSE, msg, *args, **kwargs)
+
+
+def getLogger(name: str) -> VerboseLogger:
+    """logging.getLogger, but ensures our VerboseLogger class is returned"""
+    return cast(VerboseLogger, logging.getLogger(name))
+
+
+def init_logging() -> None:
+    """Register our VerboseLogger and VERBOSE log level.
+
+    Should be called before any calls to getLogger(),
+    i.e. in pip._internal.__init__
+    """
+    logging.setLoggerClass(VerboseLogger)
+    logging.addLevelName(VERBOSE, "VERBOSE")

src/pip/_internal/utils/logging.py

@@ -4,9 +4,10 @@ import logging
 import logging.handlers
 import os
 import sys
-from logging import Filter, getLogger
+from logging import Filter
 from typing import IO, Any, Callable, Iterator, Optional, TextIO, Type, cast
 
+from pip._internal.utils._log import VERBOSE, getLogger
 from pip._internal.utils.compat import WINDOWS
 from pip._internal.utils.deprecation import DEPRECATION_MSG_PREFIX
 from pip._internal.utils.misc import ensure_dir
@@ -272,18 +273,20 @@ def setup_logging(verbosity, no_color, user_log_file):
     """
 
     # 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

@@ -6,7 +6,7 @@ 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]]
@@ -144,10 +144,10 @@ def call_subprocess(
         log_subprocess = subprocess_logger.info
         used_level = logging.INFO
     else:
-        # Then log the subprocess output using DEBUG.  This also ensures
+        # Then log the subprocess output using VERBOSE.  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 = subprocess_logger.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

@@ -102,7 +102,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,
     )
 
@@ -134,7 +134,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.