use setLoggerClass to define log.verbose

loaded in pip._internals.__init__

must use utils.logging.getLogger to get the right type annotation
instead of logging.getLogger, despite no actual difference in behavior

Author: minrk

src/pip/_internal/__init__.py

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

src/pip/_internal/commands/cache.py

@@ -1,4 +1,3 @@
-import logging
 import os
 import textwrap
 from optparse import Values
@@ -8,9 +7,9 @@
 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.logging import getLogger
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 class CacheCommand(Command):
@@ -185,7 +184,7 @@ def remove_cache_items(self, options, args):
 
         for filename in files:
             os.unlink(filename)
-            logger.log(VERBOSE, "Removed %s", filename)
+            logger.verbose("Removed %s", filename)
         logger.info("Files removed: %s", len(files))
 
     def purge_cache(self, options, args):

src/pip/_internal/commands/install.py

@@ -1,5 +1,4 @@
 import errno
-import logging
 import operator
 import os
 import shutil
@@ -28,7 +27,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.logging import getLogger
 from pip._internal.utils.misc import (
     ensure_dir,
     get_pip_version,
@@ -43,7 +42,7 @@
     should_build_for_install_command,
 )
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 def get_check_binary_allowed(format_control):
@@ -236,7 +235,7 @@ def run(self, options, args):
 
         install_options = options.install_options or []
 
-        logger.log(VERBOSE, "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,14 +4,14 @@
 providing credentials in the context of network requests.
 """
 
-import logging
 import urllib.parse
 from typing import Any, Dict, List, Optional, Tuple
 
 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.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._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 VERBOSE, 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.temp_dir import AdjacentTempDirectory, TempDirectory
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 def _script_names(dist, script_name, is_gui):
@@ -384,7 +383,7 @@ def remove(self, auto_confirm=False, verbose=False):
 
                 for path in sorted(compact(for_rename)):
                     moved.stash(path)
-                    logger.log(VERBOSE, 'Removing file or directory %s', path)
+                    logger.verbose('Removing file or directory %s', path)
 
                 for pth in self.pth.values():
                     pth.remove()
@@ -599,7 +598,7 @@ def add(self, entry):
 
     def remove(self):
         # type: () -> None
-        logger.log(VERBOSE, '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):
@@ -620,7 +619,7 @@ def remove(self):
             lines[-1] = lines[-1] + endline.encode("utf-8")
         for entry in self.entries:
             try:
-                logger.log(VERBOSE, '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():
+    """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.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
@@ -29,11 +30,6 @@
 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.
@@ -276,7 +272,6 @@ 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 >= 2:
         level_number = logging.DEBUG

src/pip/_internal/utils/subprocess.py

@@ -2,7 +2,6 @@
 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
@@ -145,9 +144,9 @@ 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 = partial(subprocess_logger.log, VERBOSE)
+        log_subprocess = subprocess_logger.verbose
         used_level = VERBOSE
 
     # Whether the subprocess will be visible in the console.