From adca155deaf497e27d05a0950c99950ca4919251 Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Fri, 15 May 2020 20:32:19 +0100 Subject: [PATCH 1/8] logger: initial verbosity/quiet counts Fixes #2332 --- dvc/cli.py | 8 ++------ dvc/logger.py | 7 ++++++- dvc/main.py | 16 ++++++++++------ 3 files changed, 18 insertions(+), 13 deletions(-) diff --git a/dvc/cli.py b/dvc/cli.py index e986c8b38f..c513566db8 100644 --- a/dvc/cli.py +++ b/dvc/cli.py @@ -116,14 +116,10 @@ def get_parent_parser(): log_level_group = parent_parser.add_mutually_exclusive_group() log_level_group.add_argument( - "-q", "--quiet", action="store_true", default=False, help="Be quiet." + "-q", "--quiet", action="count", default=0, help="Be quiet." ) log_level_group.add_argument( - "-v", - "--verbose", - action="store_true", - default=False, - help="Be verbose.", + "-v", "--verbose", action="count", default=0, help="Be verbose." ) return parent_parser diff --git a/dvc/logger.py b/dvc/logger.py index 8697ca5fba..6121c91c4c 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -7,6 +7,7 @@ from dvc.progress import Tqdm +DATABASE = 5 # logging level FOOTER = ( "\n{yellow}Having any troubles?{nc}" " Hit us up at {blue}https://dvc.org/support{nc}," @@ -116,7 +117,11 @@ def emit(self, record): def _is_verbose(): - return logging.getLogger("dvc").getEffectiveLevel() == logging.DEBUG + return ( + logging.NOTSET + < logging.getLogger("dvc").getEffectiveLevel() + <= logging.DEBUG + ) def _iter_causes(exc): diff --git a/dvc/main.py b/dvc/main.py index b4dbda9c09..5df3ea8270 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -8,7 +8,7 @@ from dvc.config import ConfigError from dvc.exceptions import DvcException, DvcParserError, NotDvcRepoError from dvc.external_repo import clean_repos -from dvc.logger import FOOTER, disable_other_loggers +from dvc.logger import DATABASE, FOOTER, disable_other_loggers from dvc.remote.pool import close_pools from dvc.utils import format_link @@ -38,11 +38,15 @@ def main(argv=None): try: args = parse_args(argv) - if args.quiet: - logger.setLevel(logging.CRITICAL) - - elif args.verbose: - logger.setLevel(logging.DEBUG) + logger.setLevel( + { + -2: logging.FATAL, + -1: logging.ERROR, + 0: logging.INFO, + 1: logging.DEBUG, + 2: DATABASE, + }[max(-2, min(args.verbose - args.quiet, 2))] + ) cmd = args.func(args) ret = cmd.run() From 9a0b6f5e9d2fd1710f3ec96255985c10a35ac25c Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Fri, 15 May 2020 20:51:55 +0100 Subject: [PATCH 2/8] actually use TRACE --- dvc/logger.py | 2 +- dvc/main.py | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index 6121c91c4c..a2871c581e 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -7,7 +7,7 @@ from dvc.progress import Tqdm -DATABASE = 5 # logging level +TRACE = 5 # logging level FOOTER = ( "\n{yellow}Having any troubles?{nc}" " Hit us up at {blue}https://dvc.org/support{nc}," diff --git a/dvc/main.py b/dvc/main.py index 5df3ea8270..71230f1a81 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -8,7 +8,7 @@ from dvc.config import ConfigError from dvc.exceptions import DvcException, DvcParserError, NotDvcRepoError from dvc.external_repo import clean_repos -from dvc.logger import DATABASE, FOOTER, disable_other_loggers +from dvc.logger import FOOTER, TRACE, disable_other_loggers from dvc.remote.pool import close_pools from dvc.utils import format_link @@ -44,7 +44,7 @@ def main(argv=None): -1: logging.ERROR, 0: logging.INFO, 1: logging.DEBUG, - 2: DATABASE, + 2: TRACE, }[max(-2, min(args.verbose - args.quiet, 2))] ) From 3be7b7359d86216d499ea0c8c5098c2b18b8d0ed Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Fri, 15 May 2020 21:09:56 +0100 Subject: [PATCH 3/8] logger: properly patch in trace --- dvc/logger.py | 38 +++++++++++++++++++++++++++++++++++++- dvc/main.py | 6 +++--- 2 files changed, 40 insertions(+), 4 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index a2871c581e..6faa6013fd 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -7,7 +7,6 @@ from dvc.progress import Tqdm -TRACE = 5 # logging level FOOTER = ( "\n{yellow}Having any troubles?{nc}" " Hit us up at {blue}https://dvc.org/support{nc}," @@ -19,6 +18,33 @@ ) +def addLoggingLevel(levelName, levelNum, methodName=None): + """ + Adds a new logging level to the `logging` module and the + currently configured logging class. + + Based on https://stackoverflow.com/questions/2183233 + """ + if methodName is None: + methodName = levelName.lower() + + assert not hasattr(logging, levelName) + assert not hasattr(logging, methodName) + assert not hasattr(logging.getLoggerClass(), methodName) + + def logForLevel(self, message, *args, **kwargs): + if self.isEnabledFor(levelNum): + self._log(levelNum, message, args, **kwargs) + + def logToRoot(message, *args, **kwargs): + logging.log(levelNum, message, *args, **kwargs) + + logging.addLevelName(levelNum, levelName) + setattr(logging, levelName, levelNum) + setattr(logging.getLoggerClass(), methodName, logForLevel) + setattr(logging, methodName, logToRoot) + + class LoggingException(Exception): def __init__(self, record): msg = "failed to log {}".format(str(record)) @@ -48,6 +74,7 @@ class ColorFormatter(logging.Formatter): """ color_code = { + "TRACE": colorama.Fore.GREEN, "DEBUG": colorama.Fore.BLUE, "WARNING": colorama.Fore.YELLOW, "ERROR": colorama.Fore.RED, @@ -157,6 +184,7 @@ def disable_other_loggers(): def setup(level=logging.INFO): colorama.init() + addLoggingLevel("TRACE", logging.DEBUG - 5) logging.config.dictConfig( { "version": 1, @@ -180,6 +208,13 @@ def setup(level=logging.INFO): "stream": "ext://sys.stdout", "filters": ["exclude_info"], }, + "console_trace": { + "class": "dvc.logger.LoggerHandler", + "level": "TRACE", + "formatter": "color", + "stream": "ext://sys.stdout", + "filters": ["exclude_info"], + }, "console_errors": { "class": "dvc.logger.LoggerHandler", "level": "WARNING", @@ -193,6 +228,7 @@ def setup(level=logging.INFO): "handlers": [ "console_info", "console_debug", + "console_trace", "console_errors", ], }, diff --git a/dvc/main.py b/dvc/main.py index 71230f1a81..8d26f85229 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -8,7 +8,7 @@ from dvc.config import ConfigError from dvc.exceptions import DvcException, DvcParserError, NotDvcRepoError from dvc.external_repo import clean_repos -from dvc.logger import FOOTER, TRACE, disable_other_loggers +from dvc.logger import FOOTER, disable_other_loggers from dvc.remote.pool import close_pools from dvc.utils import format_link @@ -18,7 +18,6 @@ "".encode("idna") - logger = logging.getLogger("dvc") @@ -44,9 +43,10 @@ def main(argv=None): -1: logging.ERROR, 0: logging.INFO, 1: logging.DEBUG, - 2: TRACE, + 2: logging.TRACE, }[max(-2, min(args.verbose - args.quiet, 2))] ) + logger.trace(args) cmd = args.func(args) ret = cmd.run() From f97a856534a2262d19ff68da1eafc5e34cd10e19 Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Fri, 15 May 2020 21:20:48 +0100 Subject: [PATCH 4/8] FATAL -> CRITICAL --- dvc/main.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dvc/main.py b/dvc/main.py index 8d26f85229..d88dcdabcb 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -39,7 +39,7 @@ def main(argv=None): logger.setLevel( { - -2: logging.FATAL, + -2: logging.CRITICAL, -1: logging.ERROR, 0: logging.INFO, 1: logging.DEBUG, From 73263463e41376d34d16b5698f593a9fcc13303f Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Sat, 16 May 2020 00:48:51 +0100 Subject: [PATCH 5/8] only change log level if not info Makes testing easier --- dvc/main.py | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/dvc/main.py b/dvc/main.py index d88dcdabcb..1c2ac8671a 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -37,15 +37,16 @@ def main(argv=None): try: args = parse_args(argv) - logger.setLevel( - { - -2: logging.CRITICAL, - -1: logging.ERROR, - 0: logging.INFO, - 1: logging.DEBUG, - 2: logging.TRACE, - }[max(-2, min(args.verbose - args.quiet, 2))] - ) + verbosity = args.verbose - args.quiet + if verbosity: + logger.setLevel( + { + -2: logging.CRITICAL, + -1: logging.ERROR, + 1: logging.DEBUG, + 2: logging.TRACE, + }[max(-2, min(verbosity, 2))] + ) logger.trace(args) cmd = args.func(args) From 0e3f2b9fc5f043ef8cb36c90c504207cd7031b85 Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Sat, 16 May 2020 01:02:22 +0100 Subject: [PATCH 6/8] tests: logger: fix and update --- tests/unit/test_logger.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 5668de133a..e85a69ec40 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -222,10 +222,11 @@ def test_progress_awareness(self, mocker, capsys, caplog): def test_handlers(): - out, deb, err = logger.handlers + out, deb, vrb, err = logger.handlers assert out.level == logging.INFO assert deb.level == logging.DEBUG + assert vrb.level == logging.TRACE assert err.level == logging.WARNING @@ -233,6 +234,7 @@ def test_logging_debug_with_datetime(caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): logger.warning("WARNING") logger.debug("DEBUG") + logger.trace("TRACE") logger.error("ERROR") for record in caplog.records: From baad6c2e3fe989604bd7215724d0bc355a4c88bc Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Sat, 16 May 2020 15:15:55 +0100 Subject: [PATCH 7/8] state: logger: debug => trace --- dvc/state.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dvc/state.py b/dvc/state.py index 928c7cad9b..3ca5091fa0 100644 --- a/dvc/state.py +++ b/dvc/state.py @@ -125,7 +125,7 @@ def __exit__(self, typ, value, tbck): self.dump() def _execute(self, cmd, parameters=()): - logger.debug(cmd) + logger.trace(cmd) return self.cursor.execute(cmd, parameters) def _fetchall(self): From 2e6558043447a3591799b8cb849d9a322fd1e4d5 Mon Sep 17 00:00:00 2001 From: Casper da Costa-Luis Date: Sat, 16 May 2020 15:26:38 +0100 Subject: [PATCH 8/8] logger: filter duplicate debug messages --- dvc/logger.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index 6faa6013fd..0d038ee01b 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -51,14 +51,12 @@ def __init__(self, record): super().__init__(msg) -class ExcludeErrorsFilter(logging.Filter): - def filter(self, record): - return record.levelno < logging.WARNING +def excludeFilter(level): + class ExcludeLevelFilter(logging.Filter): + def filter(self, record): + return record.levelno < level - -class ExcludeInfoFilter(logging.Filter): - def filter(self, record): - return record.levelno < logging.INFO + return ExcludeLevelFilter class ColorFormatter(logging.Formatter): @@ -189,8 +187,9 @@ def setup(level=logging.INFO): { "version": 1, "filters": { - "exclude_errors": {"()": ExcludeErrorsFilter}, - "exclude_info": {"()": ExcludeInfoFilter}, + "exclude_errors": {"()": excludeFilter(logging.WARNING)}, + "exclude_info": {"()": excludeFilter(logging.INFO)}, + "exclude_debug": {"()": excludeFilter(logging.DEBUG)}, }, "formatters": {"color": {"()": ColorFormatter}}, "handlers": { @@ -213,7 +212,7 @@ def setup(level=logging.INFO): "level": "TRACE", "formatter": "color", "stream": "ext://sys.stdout", - "filters": ["exclude_info"], + "filters": ["exclude_debug"], }, "console_errors": { "class": "dvc.logger.LoggerHandler",