AB#417 Updated tests of util + some whitespace handling fixes.

cotainr/pack.py

@@ -399,7 +399,7 @@ class NoEmptyLinesFilter(logging.Filter):
             """
 
             def filter(self, record):
-                return record.msg != ""
+                return record.msg.strip() != ""
 
         class OnlyFinalProgressbarFilter(logging.Filter):
             """
@@ -417,11 +417,12 @@ def filter(self, record):
                 return not self.progress_bar_re.match(record.msg)
 
         logging_filters = [
-            # The order matters as filters are applied in order.
-            # ANSI escape codes must be removed before filtering empty lines.
+            # The order matters as filters are applied in order. ANSI escape
+            # codes and partial progress bars must be removed before filtering
+            # empty lines.
             StripANSIEscapeCodes(),
-            NoEmptyLinesFilter(),
             OnlyFinalProgressbarFilter(),
+            NoEmptyLinesFilter(),
         ]
 
         return logging_filters

cotainr/tests/pack/test_conda_install.py

@@ -435,6 +435,7 @@ def test_installer_download_success(
                 b"'https://github.com/conda-forge/miniforge/releases/latest/download/Miniforge3-Linux-x86_64.sh'"
             )
 
+    @pytest.mark.conda_integration  # technically not a test that depends on Conda - but a very slow one...
     def test_installer_download_fail(
         self,
         patch_urllib_urlopen_force_fail,
@@ -481,8 +482,8 @@ def test_correctly_ordered_list_of_filters(
         ]
         assert filter_names == [
             "StripANSIEscapeCodes",
-            "NoEmptyLinesFilter",
             "OnlyFinalProgressbarFilter",
+            "NoEmptyLinesFilter",
         ]
 
     def test_strip_ANSI_codes_filter(
@@ -522,7 +523,7 @@ def test_no_empty_lines_filter(
     ):
         with SingularitySandbox(base_image="my_base_image_6021") as sandbox:
             conda_install = CondaInstall(sandbox=sandbox, license_accepted=True)
-            filter_ = conda_install._logging_filters[1]
+            filter_ = conda_install._logging_filters[2]
             assert filter_.__class__.__name__ == "NoEmptyLinesFilter"
 
         rec = logging.LogRecord(
@@ -571,7 +572,7 @@ def test_only_final_progressbar_filter(
     ):
         with SingularitySandbox(base_image="my_base_image_6021") as sandbox:
             conda_install = CondaInstall(sandbox=sandbox, license_accepted=True)
-            filter_ = conda_install._logging_filters[2]
+            filter_ = conda_install._logging_filters[1]
             assert filter_.__class__.__name__ == "OnlyFinalProgressbarFilter"
 
         rec = logging.LogRecord(

cotainr/tests/tracing/test_log_dispatcher.py

@@ -346,20 +346,19 @@ def test_log_to_correct_level(self, level, caplog):
         assert caplog.records[0].name == "test_dispatcher_6021.err"
         assert caplog.records[0].msg == "test_6021"
 
-    def test_strip_whitespace(self, caplog):
+    def test_not_stripping_whitespace(self, caplog):
         log_dispatcher = LogDispatcher(
             name="test_dispatcher_6021",
             map_log_level_func=lambda msg: logging.INFO,
             log_settings=LogSettings(verbosity=1, log_file_path=None, no_color=True),
         )
-        for msg in ["  before", "after  ", "  before and after  "]:
+        msgs = ["  before", "after  ", "  before and after  "]
+        for msg in msgs:
             log_dispatcher.log_to_stderr(msg=msg)
 
         assert len(caplog.records) == 3
         assert all(rec.name == "test_dispatcher_6021.err" for rec in caplog.records)
-        assert caplog.records[0].msg == "before"
-        assert caplog.records[1].msg == "after"
-        assert caplog.records[2].msg == "before and after"
+        assert all(msg == rec.msg for msg, rec in zip(msgs, caplog.records))
 
 
 class TestLogToStdout:
@@ -379,20 +378,19 @@ def test_log_to_correct_level(self, level, caplog):
         assert caplog.records[0].name == "test_dispatcher_6021.out"
         assert caplog.records[0].msg == "test_6021"
 
-    def test_strip_whitespace(self, caplog):
+    def test_not_stripping_whitespace(self, caplog):
         log_dispatcher = LogDispatcher(
             name="test_dispatcher_6021",
             map_log_level_func=lambda msg: logging.INFO,
             log_settings=LogSettings(verbosity=1, log_file_path=None, no_color=True),
         )
-        for msg in ["  before", "after  ", "  before and after  "]:
+        msgs = ["  before", "after  ", "  before and after  "]
+        for msg in msgs:
             log_dispatcher.log_to_stdout(msg=msg)
 
         assert len(caplog.records) == 3
         assert all(rec.name == "test_dispatcher_6021.out" for rec in caplog.records)
-        assert caplog.records[0].msg == "before"
-        assert caplog.records[1].msg == "after"
-        assert caplog.records[2].msg == "before and after"
+        assert all(msg == rec.msg for msg, rec in zip(msgs, caplog.records))
 
 
 class TestPrefixStderrName:

cotainr/tests/util/test_stream_subprocess.py

@@ -9,12 +9,14 @@
 
 import functools
 import io
+import logging
 import platform
 import subprocess
 import sys
 
 import pytest
 
+from cotainr.tracing import LogDispatcher, LogSettings
 from cotainr.util import stream_subprocess, _print_and_capture_stream
 
 
@@ -50,6 +52,63 @@ def test_kwargs_passing(self):
         )
         assert process.stdout.strip() == env["COTAINR_TEST_ENV_VAR"]
 
+    def test_logging_stdout(self, caplog):
+        log_level = logging.INFO
+        log_dispatcher = LogDispatcher(
+            name="test_dispatcher_6021",
+            map_log_level_func=lambda msg: log_level,
+            log_settings=LogSettings(verbosity=1, log_file_path=None, no_color=False),
+        )
+        stdout_text = """
+        Text on line 1
+
+        More text later!
+        """
+
+        stream_subprocess(
+            args=[
+                sys.executable,
+                "-c",
+                f"import os; os.write(1, {stdout_text.encode()})",
+            ],
+            log_dispatcher=log_dispatcher,
+        )
+
+        stdout_lines = stdout_text.splitlines(keepends=True)
+        assert len(stdout_lines) == len(caplog.records)
+        for line, rec in zip(stdout_lines, caplog.records):
+            assert rec.levelno == log_level
+            assert rec.name == "test_dispatcher_6021.out"
+            assert rec.msg == line
+
+    def test_logging_stderr(self, caplog):
+        log_level = logging.ERROR
+        log_dispatcher = LogDispatcher(
+            name="test_dispatcher_6021",
+            map_log_level_func=lambda msg: log_level,
+            log_settings=LogSettings(verbosity=0, log_file_path=None, no_color=False),
+        )
+        stderr_text = """
+        An error!
+        More breakage...
+        """
+
+        stream_subprocess(
+            args=[
+                sys.executable,
+                "-c",
+                f"import os; os.write(2, {stderr_text.encode()})",
+            ],
+            log_dispatcher=log_dispatcher,
+        )
+
+        stderr_lines = stderr_text.splitlines(keepends=True)
+        assert len(stderr_lines) == len(caplog.records)
+        for line, rec in zip(stderr_lines, caplog.records):
+            assert rec.levelno == log_level
+            assert rec.name == "test_dispatcher_6021.err"
+            assert rec.msg == line
+
     def test_stdout(self):
         stdout_text = """
         Text on line 1

cotainr/tracing.py

@@ -305,7 +305,7 @@ def log_to_stderr(self, msg):
         msg : str
             The message to log.
         """
-        self.logger_stderr.log(level=self.map_log_level(msg), msg=msg.strip())
+        self.logger_stderr.log(level=self.map_log_level(msg), msg=msg)
 
     def log_to_stdout(self, msg):
         """
@@ -319,7 +319,7 @@ def log_to_stdout(self, msg):
         msg : str
             The message to log.
         """
-        self.logger_stdout.log(level=self.map_log_level(msg), msg=msg.strip())
+        self.logger_stdout.log(level=self.map_log_level(msg), msg=msg)
 
     @contextlib.contextmanager
     def prefix_stderr_name(self, *, prefix):
@@ -437,6 +437,11 @@ def __init__(self, *, msg, stream):
             # See also: https://notes.burke.libbey.me/ansi-escape-codes/
             r"\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*([@-l]|[n-~]))"
         )
+        self._newline_at_end_re = re.compile(
+            # Find newlines at the end of a string even if the string is
+            # wrapped in a set of SGR codes.
+            r"\n(?=(?:\x1B(?:[@-Z\\-_]|\[[0-?]*[ -/]*m))+$|$)"
+        )
         self._running = False
 
         # \033[2K erases the old line to avoid the extra two characters at the
@@ -462,16 +467,16 @@ def _spin_msg(self):
         Spin the message.
 
         This is the method that the thread is running to continuously update
-        the spinnner.
+        the spinner.
         """
         # Delay spinning a bit to avoid flaky message updates when new messages
         # arrive promptly
         time.sleep(self._spinner_delay_time)
 
         # Strip any newlines and ANSI escape codes that may interfere with
         # our manipulation of the console (not SGRs, though)
-        msg = self._msg.rstrip("\n")
-        msg = self._ansi_escape_re.sub("", msg)
+        msg = self._ansi_escape_re.sub("", self._msg)
+        msg = self._newline_at_end_re.sub("", msg)
 
         # Construct a messages that is guaranteed to fit on one line with the spinner
         one_line_msg = (

cotainr/util.py

@@ -63,8 +63,9 @@ def stream_subprocess(*, args, log_dispatcher=None, **kwargs):
     Run a the command described by `args` while streaming stdout and stderr.
 
     The command described by `args` is run in a subprocess with that
-    subprocess' stdout and stderr streamed to the main process. Extra `kwargs`
-    are passed to `Popen` when opening the subprocess.
+    subprocess' stdout and stderr streamed to the main process. Each line in
+    the subprocess' output is streamed separately to the main process. Extra
+    `kwargs` are passed to `Popen` when opening the subprocess.
 
     Parameters
     ----------