Merge pull request #25 from facundobatista/logging-after-closing

Support receiving log messages (which we don't controle when happen) after machinery stopped.

IRL, this doesn't, unless somebody from the app does some logging after closing, which is improbable but possible.

The detail is that all emit.* calls are a possible input to messages, but also logging (which may be done in some thread, etc).

craft_cli/messages.py

@@ -203,6 +203,8 @@ class _Printer:
     """
 
     def __init__(self, log_filepath: pathlib.Path) -> None:
+        self.stopped = False
+
         # holder of the previous message
         self.prv_msg: Optional[_MessageInfo] = None
 
@@ -337,7 +339,10 @@ def show(
         end_line: bool = False,
         avoid_logging: bool = False,
     ) -> None:
-        """Show a text to the given stream."""
+        """Show a text to the given stream if not stopped."""
+        if self.stopped:
+            return
+
         msg = _MessageInfo(
             stream=stream,
             text=text.rstrip(),
@@ -379,6 +384,7 @@ def stop(self) -> None:
         if self.unfinished_stream is not None:
             print(flush=True, file=self.unfinished_stream)
         self.log.close()
+        self.stopped = True
 
 
 class _Progresser:

tests/conftest.py

@@ -44,6 +44,7 @@ def __init__(self, *args, **kwargs):
         self.written_bars = []
         self.logged = []
         self.spinner = RecordingSpinner(self)
+        self.spinner.start()
 
     def _write_line(self, message, *, spintext=None):
         """Overwrite the real one to avoid it and record the message and maybe the spintext."""
@@ -64,4 +65,7 @@ def _log(self, message):
 @pytest.fixture
 def recording_printer(tmp_path):
     """Provide a recording printer."""
-    return RecordingPrinter(tmp_path / "test.log")
+    recording_printer = RecordingPrinter(tmp_path / "test.log")
+    yield recording_printer
+    if not recording_printer.stopped:
+        recording_printer.stop()

tests/unit/test_messages_integration.py

@@ -736,3 +736,17 @@ def test_initial_messages_when_trace(capsys, tmp_path, monkeypatch):
         expected_err=expected_err,
         expected_log=expected_log,
     )
+
+
+def test_logging_after_closing(capsys, logger):
+    """We don't control when log messages are generated, be safe with after-stop ones."""
+    emit = Emitter()
+    emit.init(EmitterMode.VERBOSE, "testapp", GREETING)
+    logger.info("info 1")
+    emit.ended_ok()
+    logger.info("info 2")
+
+    expected = [
+        Line("info 1", timestamp=True),
+    ]
+    assert_outputs(capsys, emit, expected_err=expected, expected_log=expected)

tests/unit/test_messages_printer.py

@@ -634,6 +634,19 @@ def test_progress_bar_no_stream(recording_printer):
     assert recording_printer.prv_msg is None
 
 
+def test_show_when_stopped(recording_printer):
+    """Noop after stopping."""
+    recording_printer.stop()
+    recording_printer.show(None, "test text")
+
+    # nothing is done
+    assert not recording_printer.logged
+    assert not recording_printer.written_lines
+    assert not recording_printer.written_bars
+    assert recording_printer.prv_msg is None
+    assert not recording_printer.spinner.supervised
+
+
 # -- tests for starting/stopping the printer