diff --git a/dvc/logger.py b/dvc/logger.py index d1cf08e83a..ce4a46c04a 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -59,12 +59,28 @@ 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 ("{prefix}{description}{stack_trace}").format( + return ("{asctime}{prefix}{description}{stack_trace}").format( + asctime=self.formatTime(record, self.datefmt), prefix=self._prefix(record), description=self._description(msg, exception), stack_trace=stack_trace, ) + 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 + ): + return "" + + return "{color}{date}{nc} ".format( + color=colorama.Fore.GREEN, + date=super().formatTime(record, datefmt), + nc=colorama.Fore.RESET, + ) + def _prefix(self, record): if record.levelname == "INFO": return "" diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 1b7d906e11..83f3c7d438 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -4,6 +4,10 @@ import colorama import dvc.logger +import time +from datetime import datetime +import pytest + from dvc.exceptions import DvcException @@ -11,18 +15,29 @@ formatter = dvc.logger.ColorFormatter() colors = { "blue": colorama.Fore.BLUE, + "green": colorama.Fore.GREEN, "red": colorama.Fore.RED, "yellow": colorama.Fore.YELLOW, "nc": colorama.Fore.RESET, } +@pytest.fixture() +def dt(mocker): + with mocker.patch( + "time.time", return_value=time.mktime(datetime(2020, 2, 2).timetuple()) + ): + yield "2020-02-02 00:00:00,000" + + class TestColorFormatter: - def test_debug(self, caplog): + def test_debug(self, caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): logger.debug("message") - expected = "{blue}DEBUG{nc}: message".format(**colors) + expected = "{green}{datetime}{nc} {blue}DEBUG{nc}: message".format( + **colors, datetime=dt + ) assert expected == formatter.format(caplog.records[0]) @@ -81,7 +96,7 @@ def test_exception_with_description_and_message(self, caplog): assert expected == formatter.format(caplog.records[0]) - def test_exception_under_verbose(self, caplog): + def test_exception_under_verbose(self, caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): try: raise Exception("description") @@ -90,17 +105,21 @@ def test_exception_under_verbose(self, caplog): logger.exception("") expected = ( + "{green}{datetime}{nc} " "{red}ERROR{nc}: description\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}".format( - line="-" * 60, stack_trace=stack_trace, **colors + line="-" * 60, + stack_trace=stack_trace, + **colors, + datetime=dt ) ) assert expected == formatter.format(caplog.records[0]) - def test_tb_only(self, caplog): + def test_tb_only(self, caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): try: raise Exception("description") @@ -109,17 +128,21 @@ def test_tb_only(self, caplog): logger.exception("something", extra={"tb_only": True}) expected = ( + "{green}{datetime}{nc} " "{red}ERROR{nc}: something\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}".format( - line="-" * 60, stack_trace=stack_trace, **colors + line="-" * 60, + stack_trace=stack_trace, + **colors, + datetime=dt ) ) assert expected == formatter.format(caplog.records[0]) - def test_nested_exceptions(self, caplog): + def test_nested_exceptions(self, caplog, dt): with caplog.at_level(logging.DEBUG, logger="dvc"): try: raise Exception("first") @@ -131,11 +154,15 @@ def test_nested_exceptions(self, caplog): logger.exception("message") expected = ( + "{green}{datetime}{nc} " "{red}ERROR{nc}: message - second: first\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}".format( - line="-" * 60, stack_trace=stack_trace, **colors + line="-" * 60, + stack_trace=stack_trace, + **colors, + datetime=dt ) ) assert expected == formatter.format(caplog.records[0]) @@ -179,3 +206,21 @@ def test_handlers(): assert out.level == logging.INFO assert deb.level == logging.DEBUG assert err.level == logging.WARNING + + +def test_logging_debug_with_datetime(caplog, dt): + with caplog.at_level(logging.DEBUG, logger="dvc"): + logger.warning("WARNING") + logger.debug("DEBUG") + logger.error("ERROR") + + for record in caplog.records: + assert dt in formatter.format(record) + assert record.levelname == record.message + + +def test_info_with_debug_loglevel_shows_no_datetime(caplog, dt): + with caplog.at_level(logging.DEBUG, logger="dvc"): + logger.info("message") + + assert "message" == formatter.format(caplog.records[0])