logger: fix bug that ignored the progress bar

Close #1973

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(

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