diff --git a/dvc/logger.py b/dvc/logger.py index 95362d19cc..af96bd4acb 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -1,6 +1,6 @@ """Manages logging configuration for dvc repo.""" -import io +import traceback import logging.config import logging.handlers @@ -21,9 +21,7 @@ class LoggingException(Exception): - def __init__(self, record): - msg = "failed to log {}".format(str(record)) - super().__init__(msg) + pass class ExcludeErrorsFilter(logging.Filter): @@ -37,16 +35,12 @@ 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. """ color_code = { @@ -58,97 +52,57 @@ class ColorFormatter(logging.Formatter): } def format(self, record): + info = record.msg + if record.levelname == "INFO": - return record.msg - - if record.levelname == "ERROR" or record.levelname == "CRITICAL": - exception, stack_trace = self._parse_exc(record.exc_info) - - return ( - "{color}{levelname}{nc}: {description}" "{stack_trace}\n" - ).format( - color=self.color_code.get(record.levelname, ""), - nc=colorama.Fore.RESET, - levelname=record.levelname, - description=self._description(record.msg, exception), - msg=record.msg, - stack_trace=stack_trace, + return info + + if record.exc_info: + _, exception, _ = record.exc_info + + info = "{message}{separator}{exception}".format( + message=record.msg or "", + separator=" - " if record.msg and exception.args else "", + exception=": ".join(self._causes(exception)), ) - return "{color}{levelname}{nc}: {msg}".format( - color=self.color_code.get(record.levelname, ""), - nc=colorama.Fore.RESET, + if self._current_level() == logging.DEBUG: + trace = "".join(traceback.format_exception(*record.exc_info)) + + return ( + "{red}{levelname}{nc}: {info}\n" + "{red}{line}{nc}\n" + "{trace}" + "{red}{line}{nc}".format( + levelname=record.levelname, + info=info, + red=colorama.Fore.RED, + line="-" * 60, + trace=trace, + nc=colorama.Fore.RESET, + ) + ) + + return "{color}{levelname}{nc}: {info}".format( + color=self.color_code[record.levelname], levelname=record.levelname, - msg=record.msg, + nc=colorama.Fore.RESET, + info=info, ) - 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): - import traceback - - buffer = io.StringIO() - - traceback.print_exception(*exc_info, file=buffer) - - exc = exc_info[1] - tb = buffer.getvalue() - - exc_list = [str(exc)] - tb_list = [tb] - - # NOTE: parsing chained exceptions. See dvc/exceptions.py for more info - while hasattr(exc, "__cause__") and exc.__cause__: - exc_list.append(str(exc.__cause__)) - if hasattr(exc, "cause_tb") and exc.cause_tb: - tb_list.insert(0, str(exc.cause_tb)) + def _causes(self, exc): + while exc: + yield str(exc) exc = exc.__cause__ - return exc_list, tb_list - - def _parse_exc(self, exc_info): - if not exc_info: - return (None, "") - - exc_list, tb_list = self._walk_exc(exc_info) - - exception = ": ".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="\n".join(tb_list), - ) - else: - stack_trace = "" - - return (exception, stack_trace) + def _current_level(self): + return logging.getLogger("dvc").getEffectiveLevel() class LoggerHandler(logging.StreamHandler): def handleError(self, record): super().handleError(record) - raise LoggingException(record) + raise LoggingException("failed to log {}".format(record)) def emit(self, record): """Write to Tqdm's stream so as to not break progress-bars""" diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 201139f2eb..f60b3317c9 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -44,7 +44,7 @@ def test_error(self, caplog): with caplog.at_level(logging.INFO, logger="dvc"): logger.error("message") - expected = "{red}ERROR{nc}: message\n".format(**colors) + expected = "{red}ERROR{nc}: message".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -55,7 +55,7 @@ def test_exception(self, caplog): except Exception: logger.exception("message") - expected = "{red}ERROR{nc}: message\n".format(**colors) + expected = "{red}ERROR{nc}: message".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -66,7 +66,7 @@ def test_exception_with_description_and_without_message(self, caplog): except Exception: logger.exception("") - expected = "{red}ERROR{nc}: description\n".format(**colors) + expected = "{red}ERROR{nc}: description".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -77,9 +77,7 @@ def test_exception_with_description_and_message(self, caplog): except Exception: logger.exception("message") - expected = "{red}ERROR{nc}: message - description\n".format( - **colors - ) + expected = "{red}ERROR{nc}: message - description".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -95,7 +93,7 @@ def test_exception_under_verbose(self, caplog): "{red}ERROR{nc}: description\n" "{red}{line}{nc}\n" "{stack_trace}" - "{red}{line}{nc}\n".format( + "{red}{line}{nc}".format( line="-" * 60, stack_trace=stack_trace, **colors ) ) @@ -109,21 +107,26 @@ def test_nested_exceptions(self, caplog): except Exception as exc: try: raise DvcException("second") from exc - except DvcException: - stack_trace = traceback.format_exc() - logger.exception("message") + except DvcException as exc: + try: + raise ValueError("third") from exc + except ValueError: + stack_trace = traceback.format_exc() + logger.exception("message") expected = ( - "{red}ERROR{nc}: message - second: first\n" + "{red}ERROR{nc}: message - third: second: first\n" "{red}{line}{nc}\n" "{stack_trace}" - "{red}{line}{nc}\n".format( + "{red}{line}{nc}".format( line="-" * 60, stack_trace=stack_trace, **colors ) ) + assert expected == formatter.format(caplog.records[0]) assert "Exception: first" in stack_trace assert "dvc.exceptions.DvcException: second" in stack_trace + assert "ValueError: third" in stack_trace def test_progress_awareness(self, mocker, capsys, caplog): from dvc.progress import Tqdm