From 9978bc87a4b1fa2243880b68cfbeb4d8ed0772d3 Mon Sep 17 00:00:00 2001
From: "Mr. Outis" <mroutis@protonmail.com>
Date: Fri, 10 May 2019 00:00:45 -0700
Subject: [PATCH] logger: fix bug that ignored the progress bar

Close #1973
---
 dvc/logger.py             | 11 ++++++++++-
 tests/unit/test_logger.py | 30 ++++++++++++++++++++++++++++++
 2 files changed, 40 insertions(+), 1 deletion(-)

diff --git a/dvc/logger.py b/dvc/logger.py
index 0f428e61d..1c71a0e4f 100644
--- a/dvc/logger.py
+++ b/dvc/logger.py
@@ -47,6 +47,9 @@ class ColorFormatter(logging.Formatter):
     )
 
     def format(self, record):
+        if self._is_visible(record):
+            self._progress_aware()
+
         if record.levelname == "INFO":
             return record.msg
 
@@ -75,6 +78,12 @@ class ColorFormatter(logging.Formatter):
             msg=record.msg,
         )
 
+    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 = ""
 
@@ -117,7 +126,7 @@ class ColorFormatter(logging.Formatter):
 
         exception = ": ".join(exc_list)
 
-        if logging.getLogger("dvc").getEffectiveLevel() == logging.DEBUG:
+        if self._current_level() == logging.DEBUG:
             stack_trace = (
                 "\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}"
             ).format(
diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py
index 4149d109a..889fb4d0c 100644
--- a/tests/unit/test_logger.py
+++ b/tests/unit/test_logger.py
@@ -149,3 +149,33 @@ class TestColorFormatter:
             )
 
             assert expected == formatter.format(caplog.records[0])
+
+    def test_progress_awareness(self, mock, capsys, caplog):
+        from dvc.progress import progress
+
+        with mock.patch("sys.stdout.isatty", return_value=True):
+            progress.set_n_total(100)
+            progress.update_target("progress", 1, 10)
+
+            # logging an invisible message should not break
+            # the progress bar output
+            with caplog.at_level(logging.INFO, logger="dvc"):
+                debug_record = logging.LogRecord(
+                    name="dvc",
+                    level=logging.DEBUG,
+                    pathname=__name__,
+                    lineno=1,
+                    msg="debug",
+                    args=(),
+                    exc_info=None,
+                )
+
+                formatter.format(debug_record)
+                captured = capsys.readouterr()
+                assert "\n" not in captured.out
+
+            # just when the message is actually visible
+            with caplog.at_level(logging.INFO, logger="dvc"):
+                logger.info("some info")
+                captured = capsys.readouterr()
+                assert "\n" in captured.out