emiter: add "streaming brief" feature

This commit adds a new feature to the Emitter, tentatively called
"streaming brief". It is initially disabled, and can be enabled in
the Emitter's init() call.

Once enabled, the feature will leverage the "multi-action" nature of
progress() calls to "stream", in a single line, info-level log messages
and text written to the open_stream()'s pipe. For example, the
following sequence of calls in BRIEF mode:

```
emit.progress("Starting stage 1", permanent=False)
...
log.info("Doing first step")
...
log.info("Doing second step")
...
emit.progress("Finished stage 1", permanent=True)
```

... will cause the two 'info' messages to "stream" on the terminal,
prefixed by "Starting stage 1 ::" to indicate that they are related to
that progress message. All these three messages are ephemeral which
means that in the end only the final progress() call will be visible
on the terminal.

Fixes #165

craft_cli/messages.py

@@ -319,9 +319,16 @@ def __exit__(self, *exc_info):
 class _Handler(logging.Handler):
     """A logging handler that emits messages through the core Printer."""
 
-    def __init__(self, printer: Printer):
+    def __init__(self, printer: Printer, streaming_brief: bool = False):
+        """
+        :param printer:
+        :param bool streaming_brief:
+            Whether sys.stderr should be used as the stream when handling record
+            above DEBUG in BRIEF mode.
+        """
         super().__init__()
         self.printer = printer
+        self.streaming_brief = streaming_brief
 
         # level is 0 so we get EVERYTHING (as we need to send it all to the log file), and
         # will decide on "emit" if also goes to screen using the custom mode
@@ -347,8 +354,15 @@ def emit(self, record: logging.LogRecord) -> None:
             # in trace, everything
             stream = sys.stderr
 
+        text = record.getMessage()
+
+        ephemeral = False
+        if self.mode == EmitterMode.BRIEF and self.streaming_brief:
+            stream = sys.stderr if record.levelno > logging.DEBUG else None
+            ephemeral = True
+
         use_timestamp = self.mode in (EmitterMode.DEBUG, EmitterMode.TRACE)
-        self.printer.show(stream, record.getMessage(), use_timestamp=use_timestamp)
+        self.printer.show(stream, text, use_timestamp=use_timestamp, ephemeral=ephemeral)
 
 
 FuncT = TypeVar("FuncT", bound=Callable[..., Any])
@@ -402,6 +416,8 @@ class Emitter:
     the application behaviour and/or logs forensics.
     """
 
+    # pylint: disable=too-many-instance-attributes
+
     def __init__(self):
         # these attributes will be set at "real init time", with the `init` method below
         self._greeting = None
@@ -411,22 +427,30 @@ def __init__(self):
         self._stopped = False
         self._log_filepath = None
         self._log_handler = None
+        self._streaming_brief = False
 
     def init(
         self,
         mode: EmitterMode,
         appname: str,
         greeting: str,
         log_filepath: Optional[pathlib.Path] = None,
+        *,
+        streaming_brief: bool = False,
     ):
-        """Initialize the emitter; this must be called once and before emitting any messages."""
+        """Initialize the emitter; this must be called once and before emitting any messages.
+
+        :param streaming_brief: Whether "informational" messages should be "streamed" with
+            progress messages when using BRIEF mode.
+        """
         if self._initiated:
             if TESTMODE:
                 self._stop()
             else:
                 raise RuntimeError("Double Emitter init detected!")
 
         self._greeting = greeting
+        self._streaming_brief = streaming_brief
 
         # create a log file, bootstrap the printer, and before anything else send the greeting
         # to the file
@@ -436,7 +460,7 @@ def init(
 
         # hook into the logging system
         logger = logging.getLogger()
-        self._log_handler = _Handler(self._printer)
+        self._log_handler = _Handler(self._printer, streaming_brief=streaming_brief)
         logger.addHandler(self._log_handler)
 
         self._initiated = True
@@ -563,7 +587,18 @@ def progress(self, text: str, permanent: bool = False) -> None:
         line (unless verbose/trace mode).
         """
         stream, use_timestamp, ephemeral = self._get_progress_params(permanent)
-        self._printer.show(stream, text, ephemeral=ephemeral, use_timestamp=use_timestamp)  # type: ignore
+
+        printer = cast(Printer, self._printer)
+
+        if self._streaming_brief:
+            # Clear the "new thing" prefix, as this is a new progress message.
+            printer.set_terminal_prefix("")
+
+        printer.show(stream, text, ephemeral=ephemeral, use_timestamp=use_timestamp)  # type: ignore
+
+        if self._mode == EmitterMode.BRIEF and ephemeral and self._streaming_brief:
+            # Set the "progress prefix" for upcoming non-permanent messages.
+            printer.set_terminal_prefix(text)
 
     @_active_guard()
     def progress_bar(self, text: str, total: Union[int, float], delta: bool = True) -> _Progresser:

craft_cli/printer.py

@@ -53,6 +53,7 @@ class _MessageInfo:  # pylint: disable=too-many-instance-attributes
     use_timestamp: bool = False
     end_line: bool = False
     created_at: datetime = field(default_factory=datetime.now)
+    terminal_prefix: str = ""
 
 
 @lru_cache
@@ -161,19 +162,44 @@ def __init__(self, log_filepath: pathlib.Path) -> None:
         # keep account of output terminal streams with unfinished lines
         self.unfinished_stream: Optional[TextIO] = None
 
+        self.terminal_prefix = ""
+
         # run the spinner supervisor
         self.spinner = _Spinner(self)
         if not TESTMODE:
             self.spinner.start()
 
+    def set_terminal_prefix(self, prefix: str) -> None:
+        """Set the string to be prepended to every message shown to the terminal."""
+        self.terminal_prefix = prefix
+
+    def _get_prefixed_message_text(self, message: _MessageInfo) -> str:
+        """Get the message's text with the proper terminal prefix, if any."""
+        text = message.text
+        prefix = message.terminal_prefix
+
+        # Don't repeat text: can happen due to the spinner.
+        if prefix and text != prefix:
+            separator = ":: "
+
+            # Don't duplicate the separator, which can come from multiple different
+            # sources.
+            if text.startswith(separator):
+                separator = ""
+
+            text = f"{prefix} {separator}{text}"
+
+        return text
+
     def _write_line_terminal(self, message: _MessageInfo, *, spintext: str = "") -> None:
         """Write a simple line message to the screen."""
         # prepare the text with (maybe) the timestamp
+
+        text = self._get_prefixed_message_text(message)
+
         if message.use_timestamp:
             timestamp_str = message.created_at.isoformat(sep=" ", timespec="milliseconds")
-            text = timestamp_str + " " + message.text
-        else:
-            text = message.text
+            text = timestamp_str + " " + text
 
         if spintext:
             # forced to overwrite the previous message to present the spinner
@@ -330,6 +356,7 @@ def show(
             ephemeral=ephemeral,
             use_timestamp=use_timestamp,
             end_line=end_line,
+            terminal_prefix=self.terminal_prefix,
         )
         self._show(msg)
         if not avoid_logging:

examples.py

@@ -451,6 +451,41 @@ def example_28(mode_name, total_messages=10):
     _run_noisy_subprocess(mode_name, total_messages, example_test_sub_app)
 
 
+def example_29(mode_name, streaming_brief):
+    """Support some library logging."""
+    logger = logging.getLogger()
+    logger.setLevel(0)
+
+    mode = EmitterMode[mode_name.upper()]
+    emit.init(mode, "example_29", "Hi", streaming_brief=bool(int(streaming_brief)))
+
+    emit.progress(f"Mode set to {mode}", permanent=True)
+
+    emit.progress("Starting up lib1", permanent=False)
+    _call_lib(logger, 1)
+    emit.progress("Finished lib1", permanent=True)
+
+    emit.progress("Starting up lib2", permanent=False)
+    _call_lib(logger, 2)
+    emit.progress("Finished lib2", permanent=True)
+
+    emit.progress("Starting up lib3", permanent=False)
+    _call_lib(logger, 3)
+    emit.progress("Finished lib3", permanent=True)
+
+
+def _call_lib(logger, index):
+    lib = f"lib{index}"
+
+    time.sleep(2)
+    logger.info(f"   {lib} INFO 1")
+    logger.debug(f"   {lib} DEBUG 1")
+    time.sleep(2)
+    logger.info(f"   {lib} INFO 2")
+    logger.debug(f"   {lib} DEBUG 2")
+    time.sleep(2)
+
+
 # -- end of test cases
 
 if len(sys.argv) < 2:
@@ -463,7 +498,8 @@ def example_28(mode_name, total_messages=10):
     print(f"ERROR: function {name!r} not found")
     exit()
 
-emit.init(EmitterMode.BRIEF, "explorator", "Greetings earthlings")
+if int(sys.argv[1]) != 29:
+    emit.init(EmitterMode.BRIEF, "explorator", "Greetings earthlings")
 try:
     func(*sys.argv[2:])
 except CraftError as err:

tests/unit/test_messages_helpers.py

@@ -291,7 +291,7 @@ def test_handler_emit_full_message(handler):
     logging.getLogger().error("test message %s", 23)
 
     assert handler.printer.mock_calls == [
-        call.show(sys.stderr, "test message 23", use_timestamp=False),
+        call.show(sys.stderr, "test message 23", use_timestamp=False, ephemeral=False),
     ]
 
 
@@ -307,10 +307,10 @@ def test_handler_emit_quiet(handler):
     logger.log(5, "test custom sub-debug")
 
     assert handler.printer.mock_calls == [
-        call.show(None, "test error", use_timestamp=False),
-        call.show(None, "test warning", use_timestamp=False),
-        call.show(None, "test info", use_timestamp=False),
-        call.show(None, "test debug", use_timestamp=False),
+        call.show(None, "test error", use_timestamp=False, ephemeral=False),
+        call.show(None, "test warning", use_timestamp=False, ephemeral=False),
+        call.show(None, "test info", use_timestamp=False, ephemeral=False),
+        call.show(None, "test debug", use_timestamp=False, ephemeral=False),
     ]
 
 
@@ -326,10 +326,10 @@ def test_handler_emit_brief(handler):
     logger.log(5, "test custom sub-debug")
 
     assert handler.printer.mock_calls == [
-        call.show(None, "test error", use_timestamp=False),
-        call.show(None, "test warning", use_timestamp=False),
-        call.show(None, "test info", use_timestamp=False),
-        call.show(None, "test debug", use_timestamp=False),
+        call.show(None, "test error", use_timestamp=False, ephemeral=False),
+        call.show(None, "test warning", use_timestamp=False, ephemeral=False),
+        call.show(None, "test info", use_timestamp=False, ephemeral=False),
+        call.show(None, "test debug", use_timestamp=False, ephemeral=False),
     ]
 
 
@@ -345,10 +345,10 @@ def test_handler_emit_verbose(handler):
     logger.log(5, "test custom sub-debug")
 
     assert handler.printer.mock_calls == [
-        call.show(sys.stderr, "test error", use_timestamp=False),
-        call.show(sys.stderr, "test warning", use_timestamp=False),
-        call.show(sys.stderr, "test info", use_timestamp=False),
-        call.show(None, "test debug", use_timestamp=False),
+        call.show(sys.stderr, "test error", use_timestamp=False, ephemeral=False),
+        call.show(sys.stderr, "test warning", use_timestamp=False, ephemeral=False),
+        call.show(sys.stderr, "test info", use_timestamp=False, ephemeral=False),
+        call.show(None, "test debug", use_timestamp=False, ephemeral=False),
     ]
 
 
@@ -364,10 +364,10 @@ def test_handler_emit_debug(handler):
     logger.log(5, "test custom sub-debug")
 
     assert handler.printer.mock_calls == [
-        call.show(sys.stderr, "test error", use_timestamp=True),
-        call.show(sys.stderr, "test warning", use_timestamp=True),
-        call.show(sys.stderr, "test info", use_timestamp=True),
-        call.show(sys.stderr, "test debug", use_timestamp=True),
+        call.show(sys.stderr, "test error", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test warning", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test info", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test debug", use_timestamp=True, ephemeral=False),
     ]
 
 
@@ -383,11 +383,11 @@ def test_handler_emit_trace(handler):
     logger.log(5, "test custom sub-debug")
 
     assert handler.printer.mock_calls == [
-        call.show(sys.stderr, "test error", use_timestamp=True),
-        call.show(sys.stderr, "test warning", use_timestamp=True),
-        call.show(sys.stderr, "test info", use_timestamp=True),
-        call.show(sys.stderr, "test debug", use_timestamp=True),
-        call.show(sys.stderr, "test custom sub-debug", use_timestamp=True),
+        call.show(sys.stderr, "test error", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test warning", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test info", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test debug", use_timestamp=True, ephemeral=False),
+        call.show(sys.stderr, "test custom sub-debug", use_timestamp=True, ephemeral=False),
     ]