diff --git a/news/9450.feature.rst b/news/9450.feature.rst new file mode 100644 index 00000000000..ca3d8081ecc --- /dev/null +++ b/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. diff --git a/src/pip/_internal/__init__.py b/src/pip/_internal/__init__.py index 41071cd8608..6db42ae25a7 100755 --- a/src/pip/_internal/__init__.py +++ b/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=None): diff --git a/src/pip/_internal/commands/cache.py b/src/pip/_internal/commands/cache.py index 5155a5053e7..fac9823c1dd 100644 --- a/src/pip/_internal/commands/cache.py +++ b/src/pip/_internal/commands/cache.py @@ -1,4 +1,3 @@ -import logging import os import textwrap from optparse import Values @@ -8,8 +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 getLogger -logger = logging.getLogger(__name__) +logger = getLogger(__name__) class CacheCommand(Command): @@ -184,8 +184,8 @@ def remove_cache_items(self, options, args): 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 diff --git a/src/pip/_internal/commands/install.py b/src/pip/_internal/commands/install.py index c4273eda9cf..ff95d61f536 100644 --- a/src/pip/_internal/commands/install.py +++ b/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_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, @@ -42,7 +42,7 @@ should_build_for_install_command, ) -logger = logging.getLogger(__name__) +logger = getLogger(__name__) def get_check_binary_allowed(format_control): @@ -235,7 +235,7 @@ def run(self, options, args): 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, diff --git a/src/pip/_internal/network/auth.py b/src/pip/_internal/network/auth.py index bd54a5cba99..f92b4af2be3 100644 --- a/src/pip/_internal/network/auth.py +++ b/src/pip/_internal/network/auth.py @@ -4,7 +4,6 @@ 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.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] diff --git a/src/pip/_internal/req/req_uninstall.py b/src/pip/_internal/req/req_uninstall.py index b72234175b2..54c6f3c0dae 100644 --- a/src/pip/_internal/req/req_uninstall.py +++ b/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 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.debug('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.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): @@ -620,7 +619,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.verbose('Removing entry: %s', entry) lines.remove((entry + endline).encode("utf-8")) except ValueError: pass diff --git a/src/pip/_internal/utils/_log.py b/src/pip/_internal/utils/_log.py new file mode 100644 index 00000000000..92c4c6a1938 --- /dev/null +++ b/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") diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 45798d54f7b..0569b9248a8 100644 --- a/src/pip/_internal/utils/logging.py +++ b/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 @@ -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. diff --git a/src/pip/_internal/utils/subprocess.py b/src/pip/_internal/utils/subprocess.py index cfde1870081..19756e1acf4 100644 --- a/src/pip/_internal/utils/subprocess.py +++ b/src/pip/_internal/utils/subprocess.py @@ -6,7 +6,7 @@ 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 diff --git a/tests/functional/test_broken_stdout.py b/tests/functional/test_broken_stdout.py index cb98e31f017..4baa4348bf7 100644 --- a/tests/functional/test_broken_stdout.py +++ b/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. diff --git a/tests/functional/test_new_resolver_hashes.py b/tests/functional/test_new_resolver_hashes.py index 854b66418ae..2968760b222 100644 --- a/tests/functional/test_new_resolver_hashes.py +++ b/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, ) diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py index 9b57339c012..fa16d2fd765 100644 --- a/tests/unit/test_base_command.py +++ b/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 diff --git a/tests/unit/test_utils_subprocess.py b/tests/unit/test_utils_subprocess.py index 7a31eeb7425..2c21603c783 100644 --- a/tests/unit/test_utils_subprocess.py +++ b/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, @@ -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 @@ 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.