From 765c1feab56f8bd4b867338cc7927f0e3bd2f240 Mon Sep 17 00:00:00 2001 From: "Mr. Outis" Date: Tue, 11 Feb 2020 12:16:57 -0600 Subject: [PATCH] logger: refactor, remove dead code * 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 | 138 ++++++++++++++++---------------------- tests/unit/test_logger.py | 29 +++++++- 2 files changed, 83 insertions(+), 84 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index ce4a46c04a..ecd115a7cf 100644 --- a/dvc/logger.py +++ b/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() diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 83f3c7d438..e16323eaa7 100644 --- a/tests/unit/test_logger.py +++ b/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])