diff --git a/dvc/logger.py b/dvc/logger.py index 09b69f85f6..092f2427dd 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -87,7 +87,8 @@ class ColorFormatter(logging.Formatter): exception cause, just the message and the traceback. """ - color_code = { + reset = colorama.Fore.RESET + color_codes = { "TRACE": colorama.Fore.GREEN, "DEBUG": colorama.Fore.BLUE, "WARNING": colorama.Fore.YELLOW, @@ -95,47 +96,46 @@ class ColorFormatter(logging.Formatter): "CRITICAL": colorama.Fore.RED, } - def format(self, record): # noqa: A003 + def __init__(self, log_colors: bool = True) -> None: + super().__init__() + self.log_colors = log_colors + + def format(self, record) -> str: # noqa: A003, C901 record.message = record.getMessage() msg = self.formatMessage(record) - if record.levelname == "INFO": + if record.levelno == logging.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), - 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 not _is_verbose() or record.levelno == logging.INFO: - return "" - - return "{green}{date}{nc} ".format( - green=colorama.Fore.GREEN, - date=super().formatTime(record, datefmt), - nc=colorama.Fore.RESET, - ) + ei = record.exc_info + if ei: + cause = "" + if not getattr(record, "tb_only", False): + cause = ": ".join(_iter_causes(ei[1])) + sep = " - " if msg and cause else "" + msg = msg + sep + cause + + asctime = "" + if _is_verbose(): + asctime = self.formatTime(record, self.datefmt) + if ei and not record.exc_text: + record.exc_text = self.formatException(ei) + if record.exc_text: + if msg[-1:] != "\n": + msg = msg + "\n" + msg = msg + record.exc_text + "\n" + if record.stack_info: + if msg[-1:] != "\n": + msg = msg + "\n" + msg = msg + self.formatStack(record.stack_info) + "\n" + + level = record.levelname + if self.log_colors: + color = self.color_codes[level] + if asctime: + asctime = color + asctime + self.reset + level = color + level + self.reset + return asctime + (" " if asctime else "") + level + ": " + msg class LoggerHandler(logging.StreamHandler): @@ -180,17 +180,6 @@ def _iter_causes(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 disable_other_loggers(): logging.captureWarnings(True) loggerDict = logging.root.manager.loggerDict # pylint: disable=no-member @@ -204,9 +193,10 @@ def set_loggers_level(level: int = logging.INFO) -> None: logging.getLogger(name).setLevel(level) -def setup(level: int = logging.INFO) -> None: +def setup(level: int = logging.INFO, log_colors: bool = True) -> None: colorama.init() - formatter = ColorFormatter() + + formatter = ColorFormatter(log_colors=log_colors and sys.stdout.isatty()) console_info = LoggerHandler(sys.stdout) console_info.setLevel(logging.INFO) @@ -225,9 +215,10 @@ def setup(level: int = logging.INFO) -> None: console_trace.setFormatter(formatter) console_trace.addFilter(exclude_filter(logging.DEBUG)) + err_formatter = ColorFormatter(log_colors=log_colors and sys.stderr.isatty()) console_errors = LoggerHandler(sys.stderr) console_errors.setLevel(logging.WARNING) - console_errors.setFormatter(formatter) + console_errors.setFormatter(err_formatter) for name in ["dvc", "dvc_objects", "dvc_data"]: logger = logging.getLogger(name) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index fd4825a41f..d296863a7a 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -33,7 +33,7 @@ def test_debug(self, caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): logger.debug("message") - expected = "{green}{datetime}{nc} {blue}DEBUG{nc}: message".format( + expected = "{blue}{datetime}{nc} {blue}DEBUG{nc}: message".format( **colors, datetime=dt ) @@ -103,12 +103,9 @@ def test_exception_under_verbose(self, caplog, dt): logger.exception("") expected = ( - "{green}{datetime}{nc} " + "{red}{datetime}{nc} " "{red}ERROR{nc}: description\n" - "{red}{line}{nc}\n" - "{stack_trace}" - "{red}{line}{nc}".format( - line="-" * 60, + "{stack_trace}".format( stack_trace=stack_trace, **colors, datetime=dt, @@ -126,12 +123,9 @@ def test_exc_info_on_other_record_types(self, caplog, dt): logger.debug("", exc_info=True) expected = ( - "{green}{datetime}{nc} " + "{blue}{datetime}{nc} " "{blue}DEBUG{nc}: description\n" - "{red}{line}{nc}\n" - "{stack_trace}" - "{red}{line}{nc}".format( - line="-" * 60, + "{stack_trace}".format( stack_trace=stack_trace, datetime=dt, **colors, @@ -149,12 +143,9 @@ def test_tb_only(self, caplog, dt): logger.exception("something", extra={"tb_only": True}) expected = ( - "{green}{datetime}{nc} " + "{red}{datetime}{nc} " "{red}ERROR{nc}: something\n" - "{red}{line}{nc}\n" - "{stack_trace}" - "{red}{line}{nc}".format( - line="-" * 60, + "{stack_trace}".format( stack_trace=stack_trace, **colors, datetime=dt, @@ -175,12 +166,9 @@ def test_nested_exceptions(self, caplog, dt): logger.exception("message") expected = ( - "{green}{datetime}{nc} " + "{red}{datetime}{nc} " "{red}ERROR{nc}: message - second: first\n" - "{red}{line}{nc}\n" - "{stack_trace}" - "{red}{line}{nc}".format( - line="-" * 60, + "{stack_trace}".format( stack_trace=stack_trace, **colors, datetime=dt,