logger: add trace, count --verbose/--quiet (#3806)

* logger: initial verbosity/quiet counts

Fixes #2332

* actually use TRACE

* logger: properly patch in trace

* FATAL -> CRITICAL

* only change log level if not info

Makes testing easier

* tests: logger: fix and update

* state: logger: debug => trace

* logger: filter duplicate debug messages

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

dvc/logger.py

@@ -18,20 +18,45 @@ FOOTER = (
 )
 
 
+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))
         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):
@@ -47,6 +72,7 @@ class ColorFormatter(logging.Formatter):
     """
 
     color_code = {
+        "TRACE": colorama.Fore.GREEN,
         "DEBUG": colorama.Fore.BLUE,
         "WARNING": colorama.Fore.YELLOW,
         "ERROR": colorama.Fore.RED,
@@ -116,7 +142,11 @@ class LoggerHandler(logging.StreamHandler):
 
 
 def _is_verbose():
-    return logging.getLogger("dvc").getEffectiveLevel() == logging.DEBUG
+    return (
+        logging.NOTSET
+        < logging.getLogger("dvc").getEffectiveLevel()
+        <= logging.DEBUG
+    )
 
 
 def _iter_causes(exc):
@@ -152,12 +182,14 @@ def disable_other_loggers():
 def setup(level=logging.INFO):
     colorama.init()
 
+    addLoggingLevel("TRACE", logging.DEBUG - 5)
     logging.config.dictConfig(
         {
             "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": {
@@ -175,6 +207,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_debug"],
+                },
                 "console_errors": {
                     "class": "dvc.logger.LoggerHandler",
                     "level": "WARNING",
@@ -188,6 +227,7 @@ def setup(level=logging.INFO):
                     "handlers": [
                         "console_info",
                         "console_debug",
+                        "console_trace",
                         "console_errors",
                     ],
                 },

dvc/main.py

@@ -18,7 +18,6 @@ from dvc.utils import format_link
 
 "".encode("idna")
 
-
 logger = logging.getLogger("dvc")
 
 
@@ -38,11 +37,17 @@ def main(argv=None):
     try:
         args = parse_args(argv)
 
-        if args.quiet:
-            logger.setLevel(logging.CRITICAL)
-
-        elif args.verbose:
-            logger.setLevel(logging.DEBUG)
+        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)
         ret = cmd.run()

dvc/state.py

@@ -125,7 +125,7 @@ class State:  # pylint: disable=too-many-instance-attributes
         self.dump()
 
     def _execute(self, cmd, parameters=()):
-        logger.debug(cmd)
+        logger.trace(cmd)
         return self.cursor.execute(cmd, parameters)
 
     def _fetchall(self):

tests/unit/test_logger.py

@@ -222,10 +222,11 @@ class TestColorFormatter:
 
 
 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: