Merge pull request #6 from facundobatista/trace-message

Added a .trace method to Emitter to show trace information (CRAFT-97).

Makefile

@@ -97,7 +97,7 @@ test-pydocstyle:
 .PHONY: test-pylint
 test-pylint:
 	pylint craft_cli
-	pylint tests --disable=missing-module-docstring,missing-function-docstring,redefined-outer-name,protected-access
+	pylint tests --disable=missing-module-docstring,missing-function-docstring,redefined-outer-name,protected-access,duplicate-code
 
 .PHONY: test-pyright
 test-pyright:

craft_cli/messages.py

@@ -242,6 +242,16 @@ def message(self, text: str, intermediate: bool = False) -> None:
         )
         self.printer.show(sys.stdout, text, use_timestamp=use_timestamp)  # type: ignore
 
+    @_init_guard
+    def trace(self, text: str) -> None:
+        """Trace/debug information.
+
+        This is to record everything that the user may not want to normally see, but it's
+        useful for postmortem analysis.
+        """
+        stream = sys.stderr if self.mode == EmitterMode.TRACE else None
+        self.printer.show(stream, text, use_timestamp=True)  # type: ignore
+
     @_init_guard
     def ended_ok(self) -> None:
         """Finish the messaging system gracefully."""

tests/unit/test_messages_emitter.py

@@ -209,6 +209,34 @@ def test_message_intermediate_verboseish(get_initiated_emitter, mode):
     ]
 
 
+@pytest.mark.parametrize(
+    "mode",
+    [
+        EmitterMode.QUIET,
+        EmitterMode.NORMAL,
+        EmitterMode.VERBOSE,
+    ],
+)
+def test_trace_in_non_trace_modes(get_initiated_emitter, mode):
+    """Only log the message."""
+    emitter = get_initiated_emitter(mode)
+    emitter.trace("some text")
+
+    assert emitter.printer_calls == [
+        call().show(None, "some text", use_timestamp=True),
+    ]
+
+
+def test_trace_in_trace_mode(get_initiated_emitter):
+    """Lof the message and show it in stderr."""
+    emitter = get_initiated_emitter(EmitterMode.TRACE)
+    emitter.trace("some text")
+
+    assert emitter.printer_calls == [
+        call().show(sys.stderr, "some text", use_timestamp=True),
+    ]
+
+
 # -- tests for stopping the machinery
 
 

tests/unit/test_messages_integration.py

@@ -183,6 +183,40 @@ def test_01_intermediate_message_verbose(capsys, mode):
     assert_outputs(capsys, emit, expected_out=expected, expected_log=expected)
 
 
+@pytest.mark.parametrize(
+    "mode",
+    [
+        EmitterMode.QUIET,
+        EmitterMode.NORMAL,
+        EmitterMode.VERBOSE,
+    ],
+)
+def test_04_5_trace_other_modes(capsys, mode, monkeypatch):
+    """Internal trace for other modes."""
+    emit = Emitter()
+    emit.init(mode, "testapp", GREETING)
+    emit.trace("The meaning of life is 42.")
+    emit.ended_ok()
+
+    expected = [
+        Line("The meaning of life is 42.", timestamp=True),
+    ]
+    assert_outputs(capsys, emit, expected_log=expected)
+
+
+def test_04_5_trace_in_trace(capsys):
+    """Internal trace when in trace mode."""
+    emit = Emitter()
+    emit.init(EmitterMode.TRACE, "testapp", GREETING)
+    emit.trace("The meaning of life is 42.")
+    emit.ended_ok()
+
+    expected = [
+        Line("The meaning of life is 42.", timestamp=True),
+    ]
+    assert_outputs(capsys, emit, expected_err=expected, expected_log=expected)
+
+
 @pytest.mark.parametrize(
     "mode",
     [
@@ -199,7 +233,9 @@ def test_initial_messages_when_quietish(capsys, mode, monkeypatch, tmp_path):
 
     emit = Emitter()
     emit.init(EmitterMode.NORMAL, "testapp", different_greeting)
+    emit.trace("initial trace")
     emit.set_mode(mode)
+    emit.trace("second trace")
     emit.message("final message")
     emit.ended_ok()
 
@@ -208,6 +244,8 @@ def test_initial_messages_when_quietish(capsys, mode, monkeypatch, tmp_path):
     ]
     expected_log = [
         Line(different_greeting),
+        Line("initial trace"),
+        Line("second trace"),
         Line("final message"),
     ]
     assert_outputs(capsys, emit, expected_out=expected_out, expected_log=expected_log)
@@ -222,7 +260,9 @@ def test_initial_messages_when_verbose(capsys, tmp_path, monkeypatch):
 
     emit = Emitter()
     emit.init(EmitterMode.NORMAL, "testapp", different_greeting)
+    emit.trace("initial trace")
     emit.set_mode(EmitterMode.VERBOSE)
+    emit.trace("second trace")
     emit.message("final message")
     emit.ended_ok()
 
@@ -235,6 +275,8 @@ def test_initial_messages_when_verbose(capsys, tmp_path, monkeypatch):
     ]
     expected_log = [
         Line(different_greeting),
+        Line("initial trace"),
+        Line("second trace"),
         Line("final message"),
     ]
     assert_outputs(
@@ -255,7 +297,9 @@ def test_initial_messages_when_trace(capsys, tmp_path, monkeypatch):
 
     emit = Emitter()
     emit.init(EmitterMode.NORMAL, "testapp", different_greeting)
+    emit.trace("initial trace")
     emit.set_mode(EmitterMode.TRACE)
+    emit.trace("second trace")
     emit.message("final message")
     emit.ended_ok()
 
@@ -265,9 +309,12 @@ def test_initial_messages_when_trace(capsys, tmp_path, monkeypatch):
     expected_err = [
         Line(different_greeting, timestamp=True),
         Line(f"Logging execution to '{different_logpath}'", timestamp=True),
+        Line("second trace", timestamp=True),
     ]
     expected_log = [
         Line(different_greeting),
+        Line("initial trace"),
+        Line("second trace"),
         Line("final message"),
     ]
     assert_outputs(