logger: refactor, remove dead code (#3306)

* Remove dead code
* Rename _walk_exc to _causes, simplify it
* Split up stack trace and remove extra \n
* Import traceback only when needed

dvc/logger.py

@@ -1,6 +1,5 @@
 """Manages logging configuration for DVC repo."""
 
-import traceback
 import logging.config
 import logging.handlers
 
@@ -37,16 +36,15 @@ def filter(self, record):
 
 
 class ColorFormatter(logging.Formatter):
-    """Enable color support when logging to a terminal that supports it.
+    """Spit out colored text in supported terminals.
 
-    Color support on Windows versions that do not support ANSI color codes is
-    enabled by use of the colorama__ library.
+    colorama__ makes ANSI escape character sequences work under Windows.
     See the colorama documentation for details.
 
     __ https://pypi.python.org/pypi/colorama
 
-    For records containing `exc_info`, it will use a custom `_walk_exc` to
-    retrieve the whole traceback.
+    If record has an extra `tb_only` attribute, it will not show the
+    exception cause, just the message and the traceback.
     """
 
     color_code = {
@@ -58,93 +56,45 @@ class ColorFormatter(logging.Formatter):
 
     def format(self, record):
         msg = record.msg.format(*record.args) if record.args else record.msg
-        exception, stack_trace = self._parse_exc(record)
-        return ("{asctime}{prefix}{description}{stack_trace}").format(
+
+        if record.levelname == "INFO":
+            return msg
+
+        if record.exc_info:
+            if getattr(record, "tb_only", False):
+                cause = ""
+            else:
+                cause = ": ".join(_iter_causes(record.exc_info[1]))
+
+            msg = "{message}{separator}{cause}".format(
+                message=msg or "",
+                separator=" - " if msg and cause else "",
+                cause=cause,
+            )
+
+            if _is_verbose():
+                msg += _stack_trace(record.exc_info)
+
+        return "{asctime}{color}{levelname}{nc}: {msg}".format(
             asctime=self.formatTime(record, self.datefmt),
-            prefix=self._prefix(record),
-            description=self._description(msg, exception),
-            stack_trace=stack_trace,
+            color=self.color_code[record.levelname],
+            nc=colorama.Fore.RESET,
+            levelname=record.levelname,
+            msg=msg,
         )
 
     def formatTime(self, record, datefmt=None):
         # only show if current level is set to DEBUG
         # also, skip INFO as it is used for UI
-        if (
-            self._current_level() != logging.DEBUG
-            or record.levelno == logging.INFO
-        ):
+        if not _is_verbose() or record.levelno == logging.INFO:
             return ""
 
-        return "{color}{date}{nc} ".format(
-            color=colorama.Fore.GREEN,
+        return "{green}{date}{nc} ".format(
+            green=colorama.Fore.GREEN,
             date=super().formatTime(record, datefmt),
             nc=colorama.Fore.RESET,
         )
 
-    def _prefix(self, record):
-        if record.levelname == "INFO":
-            return ""
-
-        return "{color}{levelname}{nc}: ".format(
-            color=self.color_code.get(record.levelname, ""),
-            levelname=record.levelname,
-            nc=colorama.Fore.RESET,
-        )
-
-    def _current_level(self):
-        return logging.getLogger("dvc").getEffectiveLevel()
-
-    def _is_visible(self, record):
-        return record.levelno >= self._current_level()
-
-    def _description(self, message, exception):
-        description = ""
-
-        if exception and message:
-            description = "{message} - {exception}"
-        elif exception:
-            description = "{exception}"
-        elif message:
-            description = "{message}"
-
-        return description.format(message=message, exception=exception)
-
-    def _walk_exc(self, exc_info):
-        exc = exc_info[1]
-
-        exc_list = [str(exc)]
-
-        while hasattr(exc, "__cause__") and exc.__cause__:
-            exc_list.append(str(exc.__cause__))
-            exc = exc.__cause__
-
-        return exc_list
-
-    def _parse_exc(self, record):
-        tb_only = getattr(record, "tb_only", False)
-
-        if not record.exc_info:
-            return (None, "")
-
-        exc_list = self._walk_exc(record.exc_info)
-        tb = traceback.format_exception(*record.exc_info)
-
-        exception = None if tb_only else ": ".join(exc_list)
-
-        if self._current_level() == logging.DEBUG:
-            stack_trace = (
-                "\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}"
-            ).format(
-                red=colorama.Fore.RED,
-                nc=colorama.Fore.RESET,
-                line="-" * 60,
-                stack_trace="".join(tb),
-            )
-        else:
-            stack_trace = ""
-
-        return (exception, stack_trace)
-
 
 class LoggerHandler(logging.StreamHandler):
     def handleError(self, record):
@@ -165,6 +115,32 @@ def emit(self, record):
             self.handleError(record)
 
 
+def _is_verbose():
+    return logging.getLogger("dvc").getEffectiveLevel() == logging.DEBUG
+
+
+def _iter_causes(exc):
+    while exc:
+        yield str(exc)
+        exc = exc.__cause__
+
+
+def _stack_trace(exc_info):
+    import traceback
+
+    return (
+        "\n"
+        "{red}{line}{nc}\n"
+        "{trace}"
+        "{red}{line}{nc}".format(
+            red=colorama.Fore.RED,
+            line="-" * 60,
+            trace="".join(traceback.format_exception(*exc_info)),
+            nc=colorama.Fore.RESET,
+        )
+    )
+
+
 def setup(level=logging.INFO):
     colorama.init()
 

tests/unit/test_logger.py

@@ -113,7 +113,30 @@ def test_exception_under_verbose(self, caplog, dt):
                     line="-" * 60,
                     stack_trace=stack_trace,
                     **colors,
-                    datetime=dt
+                    datetime=dt,
+                )
+            )
+
+            assert expected == formatter.format(caplog.records[0])
+
+    def test_exc_info_on_other_record_types(self, caplog, dt):
+        with caplog.at_level(logging.DEBUG, logger="dvc"):
+            try:
+                raise Exception("description")
+            except Exception:
+                stack_trace = traceback.format_exc()
+                logger.debug("", exc_info=True)
+
+            expected = (
+                "{green}{datetime}{nc} "
+                "{blue}DEBUG{nc}: description\n"
+                "{red}{line}{nc}\n"
+                "{stack_trace}"
+                "{red}{line}{nc}".format(
+                    line="-" * 60,
+                    stack_trace=stack_trace,
+                    datetime=dt,
+                    **colors,
                 )
             )
 
@@ -136,7 +159,7 @@ def test_tb_only(self, caplog, dt):
                     line="-" * 60,
                     stack_trace=stack_trace,
                     **colors,
-                    datetime=dt
+                    datetime=dt,
                 )
             )
 
@@ -162,7 +185,7 @@ def test_nested_exceptions(self, caplog, dt):
                     line="-" * 60,
                     stack_trace=stack_trace,
                     **colors,
-                    datetime=dt
+                    datetime=dt,
                 )
             )
             assert expected == formatter.format(caplog.records[0])