From e7b7239be35b717fadf77e12fca59efcf1f79b4f Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 26 Jun 2018 15:15:40 +0530 Subject: [PATCH 1/6] Move all logging setup into a separate function --- src/pip/_internal/basecommand.py | 93 +++--------------------------- src/pip/_internal/utils/logging.py | 90 +++++++++++++++++++++++++++++ 2 files changed, 99 insertions(+), 84 deletions(-) diff --git a/src/pip/_internal/basecommand.py b/src/pip/_internal/basecommand.py index 64411697b..4a3033bf2 100644 --- a/src/pip/_internal/basecommand.py +++ b/src/pip/_internal/basecommand.py @@ -24,7 +24,7 @@ from pip._internal.status_codes import ( ERROR, PREVIOUS_BUILD_DIR_ERROR, SUCCESS, UNKNOWN_ERROR, VIRTUALENV_NOT_FOUND, ) -from pip._internal.utils.logging import IndentingFormatter +from pip._internal.utils.logging import setup_logging from pip._internal.utils.misc import get_prog, normalize_path from pip._internal.utils.outdated import pip_version_check from pip._internal.utils.typing import MYPY_CHECK_RUNNING @@ -42,7 +42,6 @@ class Command(object): usage = None # type: Optional[str] hidden = False # type: bool ignore_require_venv = False # type: bool - log_streams = ("ext://sys.stdout", "ext://sys.stderr") def __init__(self, isolated=False): parser_kw = { @@ -114,89 +113,15 @@ class Command(object): # Set verbosity so that it can be used elsewhere. self.verbosity = options.verbose - options.quiet - if self.verbosity >= 1: - level = "DEBUG" - elif self.verbosity == -1: - level = "WARNING" - elif self.verbosity == -2: - level = "ERROR" - elif self.verbosity <= -3: - level = "CRITICAL" - else: - level = "INFO" + setup_logging( + verbosity=self.verbosity, + additional_log_file=options.log, + no_color=options.no_color, + ) - # The root logger should match the "console" level *unless* we - # specified "--log" to send debug logs to a file. - root_level = level - if options.log: - root_level = "DEBUG" - - logger_class = "pip._internal.utils.logging.ColorizedStreamHandler" - handler_class = "pip._internal.utils.logging.BetterRotatingFileHandler" - - logging.config.dictConfig({ - "version": 1, - "disable_existing_loggers": False, - "filters": { - "exclude_warnings": { - "()": "pip._internal.utils.logging.MaxLevelFilter", - "level": logging.WARNING, - }, - }, - "formatters": { - "indent": { - "()": IndentingFormatter, - "format": "%(message)s", - }, - }, - "handlers": { - "console": { - "level": level, - "class": logger_class, - "no_color": options.no_color, - "stream": self.log_streams[0], - "filters": ["exclude_warnings"], - "formatter": "indent", - }, - "console_errors": { - "level": "WARNING", - "class": logger_class, - "no_color": options.no_color, - "stream": self.log_streams[1], - "formatter": "indent", - }, - "user_log": { - "level": "DEBUG", - "class": handler_class, - "filename": options.log or "/dev/null", - "delay": True, - "formatter": "indent", - }, - }, - "root": { - "level": root_level, - "handlers": list(filter(None, [ - "console", - "console_errors", - "user_log" if options.log else None, - ])), - }, - # Disable any logging besides WARNING unless we have DEBUG level - # logging enabled. These use both pip._vendor and the bare names - # for the case where someone unbundles our libraries. - "loggers": { - name: { - "level": ( - "WARNING" if level in ["INFO", "ERROR"] else "DEBUG" - ) - } for name in [ - "pip._vendor", "distlib", "requests", "urllib3" - ] - }, - }) - - # TODO: try to get these passing down from the command? - # without resorting to os.environ to hold these. + # TODO: Try to get these passing down from the command? + # without resorting to os.environ to hold these. + # This also affects isolated builds and it should. if options.no_input: os.environ['PIP_NO_INPUT'] = '1' diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 0c1495dac..0dc029466 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -130,3 +130,93 @@ class MaxLevelFilter(logging.Filter): def filter(self, record): return record.levelno < self.level + + +def setup_logging(verbosity, additional_log_file, no_color): + """Configures and sets up all of the logging + """ + + # Determine the level to be logging at. + if verbosity >= 1: + level = "DEBUG" + elif verbosity == -1: + level = "WARNING" + elif verbosity == -2: + level = "ERROR" + elif verbosity <= -3: + level = "CRITICAL" + else: + level = "INFO" + + # The "root" logger should match the "console" level *unless* we specified + # a "--log" file to send debug logs. + root_level = level + if additional_log_file is not None: + root_level = "DEBUG" + + # Shorthand for clarity + log_streams = ("ext://sys.stdout", "ext://sys.stderr") + + logger_class = "pip._internal.utils.logging.ColorizedStreamHandler" + handler_class = "pip._internal.utils.logging.BetterRotatingFileHandler" + + logging.config.dictConfig({ + "version": 1, + "disable_existing_loggers": False, + "filters": { + "exclude_warnings": { + "()": "pip._internal.utils.logging.MaxLevelFilter", + "level": logging.WARNING, + }, + }, + "formatters": { + "indent": { + "()": IndentingFormatter, + "format": "%(message)s", + }, + }, + "handlers": { + "console": { + "level": level, + "class": logger_class, + "no_color": no_color, + "stream": log_streams[0], + "filters": ["exclude_warnings"], + "formatter": "indent", + }, + "console_errors": { + "level": "WARNING", + "class": logger_class, + "no_color": no_color, + "stream": log_streams[1], + "formatter": "indent", + }, + "user_log": { + "level": "DEBUG", + "class": handler_class, + "filename": additional_log_file or "/dev/null", + "delay": True, + "formatter": "indent", + }, + }, + "root": { + "level": root_level, + "handlers": list(filter(None, [ + "console", + "console_errors", + "user_log" if additional_log_file else None, + ])), + }, + # Disable any logging besides WARNING unless we have DEBUG level + # logging enabled. These use both pip._vendor and the bare names + # for the case where someone unbundles our libraries. + "loggers": { + name: { + "level": ( + "WARNING" if level in ["INFO", "ERROR"] else "DEBUG" + ) + } for name in [ + "pip._vendor", "distlib", "requests", "urllib3" + ] + }, + }) From 036e5c8eec6322b1110fec43f88742dca63c70c1 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 26 Jun 2018 15:23:19 +0530 Subject: [PATCH 2/6] Simply shutdown logging instead of cleaning up --- src/pip/_internal/basecommand.py | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/src/pip/_internal/basecommand.py b/src/pip/_internal/basecommand.py index 4a3033bf2..8abf4e1f6 100644 --- a/src/pip/_internal/basecommand.py +++ b/src/pip/_internal/basecommand.py @@ -137,8 +137,6 @@ class Command(object): ) sys.exit(VIRTUALENV_NOT_FOUND) - original_root_handlers = set(logging.root.handlers) - try: status = self.run(options, args) # FIXME: all commands should return an exit status @@ -178,10 +176,9 @@ class Command(object): retries=0, timeout=min(5, options.timeout)) as session: pip_version_check(session, options) - # Avoid leaking loggers - for handler in set(logging.root.handlers) - original_root_handlers: - # this method benefit from the Logger class internal lock - logging.root.removeHandler(handler) + + # Shutdown the logging module + logging.shutdown() return SUCCESS From 621ff77c94f4d76f199fef857fdd5b3e99bfba3a Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 26 Jun 2018 15:29:11 +0530 Subject: [PATCH 3/6] Improve readability of logging setup --- src/pip/_internal/utils/logging.py | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 0dc029466..2432191d4 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -154,11 +154,15 @@ def setup_logging(verbosity, additional_log_file, no_color): if additional_log_file is not None: root_level = "DEBUG" - # Shorthand for clarity - log_streams = ("ext://sys.stdout", "ext://sys.stderr") - - logger_class = "pip._internal.utils.logging.ColorizedStreamHandler" - handler_class = "pip._internal.utils.logging.BetterRotatingFileHandler" + # Shorthands for clarity + log_streams = { + "stdout": "ext://sys.stdout", + "stderr": "ext://sys.stderr", + } + handler_classes = { + "stream": "pip._internal.utils.logging.ColorizedStreamHandler", + "file": "pip._internal.utils.logging.BetterRotatingFileHandler", + } logging.config.dictConfig({ "version": 1, @@ -178,22 +182,22 @@ def setup_logging(verbosity, additional_log_file, no_color): "handlers": { "console": { "level": level, - "class": logger_class, + "class": handler_classes["stream"], "no_color": no_color, - "stream": log_streams[0], + "stream": log_streams["stdout"], "filters": ["exclude_warnings"], "formatter": "indent", }, "console_errors": { "level": "WARNING", - "class": logger_class, + "class": handler_classes["stream"], "no_color": no_color, - "stream": log_streams[1], + "stream": log_streams["stderr"], "formatter": "indent", }, "user_log": { "level": "DEBUG", - "class": handler_class, + "class": handler_classes["file"], "filename": additional_log_file or "/dev/null", "delay": True, "formatter": "indent", From ba5315956e159f882e811f079a13834ae609ea69 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 26 Jun 2018 15:31:20 +0530 Subject: [PATCH 4/6] Make it clearer when user_log is used --- src/pip/_internal/utils/logging.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 2432191d4..ec3804e2e 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -205,11 +205,9 @@ def setup_logging(verbosity, additional_log_file, no_color): }, "root": { "level": root_level, - "handlers": list(filter(None, [ - "console", - "console_errors", - "user_log" if additional_log_file else None, - ])), + "handlers": ["console", "console_errors"] + ( + ["user_log"] if additional_log_file else [] + ), }, # Disable any logging besides WARNING unless we have DEBUG level # logging enabled. These use both pip._vendor and the bare names From f19d1fc3451d71cb9d531a351d77f2e76b9a71f7 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Tue, 26 Jun 2018 16:07:58 +0530 Subject: [PATCH 5/6] Cleanup logic surrounding user_log handler --- src/pip/_internal/basecommand.py | 2 +- src/pip/_internal/utils/logging.py | 19 ++++++++++++------- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/src/pip/_internal/basecommand.py b/src/pip/_internal/basecommand.py index 8abf4e1f6..edb3ed9a0 100644 --- a/src/pip/_internal/basecommand.py +++ b/src/pip/_internal/basecommand.py @@ -115,8 +115,8 @@ class Command(object): setup_logging( verbosity=self.verbosity, - additional_log_file=options.log, no_color=options.no_color, + user_log_file=options.log, ) # TODO: Try to get these passing down from the command? diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index ec3804e2e..839d8814d 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -132,7 +132,7 @@ class MaxLevelFilter(logging.Filter): return record.levelno < self.level -def setup_logging(verbosity, additional_log_file, no_color): +def setup_logging(verbosity, no_color, user_log_file): """Configures and sets up all of the logging """ @@ -148,11 +148,16 @@ def setup_logging(verbosity, additional_log_file, no_color): else: level = "INFO" - # The "root" logger should match the "console" level *unless* we specified - # a "--log" file to send debug logs. - root_level = level - if additional_log_file is not None: + # The "root" logger should match the "console" level *unless* we also need + # to log to a user log file. + include_user_log = user_log_file is not None + if include_user_log: + additional_log_file = user_log_file root_level = "DEBUG" + else: + additional_log_file = "/dev/null" + root_level = level + # Shorthands for clarity log_streams = { @@ -198,7 +203,7 @@ def setup_logging(verbosity, additional_log_file, no_color): "user_log": { "level": "DEBUG", "class": handler_classes["file"], - "filename": additional_log_file or "/dev/null", + "filename": additional_log_file, "delay": True, "formatter": "indent", }, @@ -206,7 +211,7 @@ def setup_logging(verbosity, additional_log_file, no_color): "root": { "level": root_level, "handlers": ["console", "console_errors"] + ( - ["user_log"] if additional_log_file else [] + ["user_log"] if include_user_log else [] ), }, # Disable any logging besides WARNING unless we have DEBUG level From e8caa3173670edea36ee498179bbaf94381b9290 Mon Sep 17 00:00:00 2001 From: Pradyun Gedam Date: Wed, 27 Jun 2018 12:07:29 +0530 Subject: [PATCH 6/6] Disable logging only for vendored dependencies The current list is already not up-to-date. This should be handled by downstream packagers if they unvendor pip's dependencies. --- src/pip/_internal/utils/logging.py | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 839d8814d..c2a2f9d81 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -158,6 +158,9 @@ def setup_logging(verbosity, no_color, user_log_file): additional_log_file = "/dev/null" root_level = level + # Disable any logging besides WARNING unless we have DEBUG level logging + # enabled for vendored libraries. + vendored_log_level = "WARNING" if level in ["INFO", "ERROR"] else "DEBUG" # Shorthands for clarity log_streams = { @@ -214,16 +217,9 @@ def setup_logging(verbosity, no_color, user_log_file): ["user_log"] if include_user_log else [] ), }, - # Disable any logging besides WARNING unless we have DEBUG level - # logging enabled. These use both pip._vendor and the bare names - # for the case where someone unbundles our libraries. "loggers": { - name: { - "level": ( - "WARNING" if level in ["INFO", "ERROR"] else "DEBUG" - ) - } for name in [ - "pip._vendor", "distlib", "requests", "urllib3" - ] + "pip._vendor": { + "level": vendored_log_level + } }, })