Repository: databrickslabs/blueprint

Issue:
[BUG] Inconsistent log formatting for `WARNING` and `CRITICAL` categories
The Python logging system has `WARN` and `FATAL` levels, as convenient aliases for `WARNING` and `FATAL`. At the moment the custom logging configuration that Blueprint installs is inconsistent in how these categories are logged:

 - If `color` output is disabled, the names `WARNING` and `CRITICAL` are used, as is the norm for Python application.
 - If `color` output is enabled, the names `WARN` and `FATAL` are used instead. This is inconsistent with both the uncolorized output and Python norms.

Although the terms `WARN` and `FATAL` are slightly shorter, the benefit is probably outweighed by diverging from the expected norms of the ecosystem and inconsistent terms depending on the configuration.

Discussion:

Solution patch:
diff --git a/src/databricks/labs/blueprint/logger.py b/src/databricks/labs/blueprint/logger.py
index 848590a..e9ab481 100644
--- a/src/databricks/labs/blueprint/logger.py
+++ b/src/databricks/labs/blueprint/logger.py
@@ -23,6 +23,12 @@ class NiceFormatter(logging.Formatter):
     colors: bool
     """Whether this formatter is formatting with colors or not."""
 
+    _levels: dict[int, str]
+    """The colorized level names for each logging level."""
+
+    _msg_colors: dict[int, str]
+    """The color codes to use for rendering the message text depending on the logging level."""
+
     def __init__(self, *, probe_tty: bool = False, stream: TextIO = sys.stdout) -> None:
         """Create a new instance of the formatter.
 
@@ -31,13 +37,21 @@ class NiceFormatter(logging.Formatter):
             probe_tty: If true, the formatter will enable color support if the output stream appears to be a console.
         """
         super().__init__(fmt="%(asctime)s %(levelname)s [%(name)s] %(message)s", datefmt="%H:%M:%S")
+        # Used to colorize the level names.
         self._levels = {
-            logging.NOTSET: self._bold("TRACE"),
-            logging.DEBUG: self._bold(f"{self.CYAN}DEBUG"),
-            logging.INFO: self._bold(f"{self.GREEN} INFO"),
-            logging.WARNING: self._bold(f"{self.YELLOW} WARN"),
-            logging.ERROR: self._bold(f"{self.RED}ERROR"),
-            logging.CRITICAL: self._bold(f"{self.MAGENTA}FATAL"),
+            logging.DEBUG: self._bold(f"{self.CYAN}   DEBUG"),
+            logging.INFO: self._bold(f"{self.GREEN}    INFO"),
+            logging.WARNING: self._bold(f"{self.YELLOW} WARNING"),
+            logging.ERROR: self._bold(f"{self.RED}   ERROR"),
+            logging.CRITICAL: self._bold(f"{self.MAGENTA}CRITICAL"),
+        }
+        # Used to colorize the message text. (These are prefixes: after the message text, the color is reset.)
+        self._msg_colors = {
+            logging.DEBUG: self.GRAY,
+            logging.INFO: self.BOLD,
+            logging.WARNING: self.BOLD,
+            logging.ERROR: f"{self.BOLD}{self.RED}",
+            logging.CRITICAL: f"{self.BOLD}{self.RED}",
         }
         # show colors in runtime, github actions, and while debugging
         self.colors = stream.isatty() if probe_tty else True
@@ -52,10 +66,13 @@ class NiceFormatter(logging.Formatter):
             return super().format(record)
         timestamp = self.formatTime(record, datefmt="%H:%M:%S")
         level = self._levels[record.levelno]
+
         # databricks.labs.ucx.foo.bar -> d.l.u.foo.bar
         module_split = record.name.split(".")
-        last_two_modules = len(module_split) - 2
-        name = ".".join(part if i >= last_two_modules else part[0] for i, part in enumerate(module_split))
+        abbreviated = [c[:1] for c in module_split[:-2]]  # abbreviate all but the last two components
+        as_is = module_split[-2:]  # keep the last two components as-is
+        name = ".".join([*abbreviated, *as_is])
+
         msg = record.getMessage()
         if record.exc_info and not record.exc_text:
             record.exc_text = self.formatException(record.exc_info)
@@ -66,11 +83,7 @@ class NiceFormatter(logging.Formatter):
                 msg += "\n"
             msg += self.formatStack(record.stack_info)
 
-        color_marker = self.GRAY
-        if record.levelno in (logging.INFO, logging.WARNING):
-            color_marker = self.BOLD
-        elif record.levelno in (logging.ERROR, logging.FATAL):
-            color_marker = self.RED + self.BOLD
+        color_marker = self._msg_colors[record.levelno]
 
         thread_name = f"[{record.threadName}]" if record.threadName != "MainThread" else ""
         return f"{self.GRAY}{timestamp}{self.RESET} {level} {color_marker}[{name}]{thread_name} {msg}{self.RESET}"


Test patch:
diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py
index ba8f69e..f477af4 100644
--- a/tests/unit/test_logger.py
+++ b/tests/unit/test_logger.py
@@ -252,20 +252,8 @@ def test_formatter_format_log_level(level: int, use_colors: bool) -> None:
     formatted = formatter.format(record)
     stripped = _strip_sgr_sequences(formatted) if use_colors else formatted
 
-    # Can't mark combinations of parameters for xfail, so we simulate it here.
-    expected_failure = use_colors and level in (logging.WARNING, logging.CRITICAL)
-    try:
-        # H:M:S LEVEL [logger_name] message
-        assert f" {logging.getLevelName(level)} " in stripped
-        if expected_failure:
-            msg = (
-                f"Unexpected success: colorized log-level for {logging.getLevelName(level)} is thought to be incorrect."
-            )
-            pytest.fail(msg)
-    except AssertionError:
-        if not expected_failure:
-            raise
-        pytest.xfail(f"Colorized log-level formatting for {logging.getLevelName(level)} is known to be incorrect.")
+    # H:M:S LEVEL [logger_name] message
+    assert f" {logging.getLevelName(level)} " in stripped
 
 
 # Logger names, and their abbreviated forms.
@@ -288,17 +276,7 @@ def test_formatter_format_colorized_logger_name_abbreviated(logger_name: str, fo
 
     # Create a log record with the specified level.
     record = create_record(logging.DEBUG, "Whatever", name=logger_name)
-    # Can't easily mark this as known to sometimes faili, so we simulate it here.
-    expected_failure = ".." in logger_name
-    try:
-        formatted = formatter.format(record)
-        if expected_failure:
-            pytest.fail("Unexpected success: colorized logger name abbreviation is though to fail when .. is present.")
-    except IndexError:
-        if not expected_failure:
-            raise
-        pytest.xfail("Colorized logger name abbreviation is known to fail when .. is present.")
-        return
+    formatted = formatter.format(record)
     stripped = _strip_sgr_sequences(formatted)
 
     # H:M:S LEVEL [logger_name] message